2021-11-17T18:06:53.819Z,1637172413.819 [Supervisor](DEBUG): Initializing supervisor.
2021-11-17T18:06:53.824Z,1637172413.824 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2021-11-17T18:06:53.825Z,1637172413.825 [SyncHandler](INFO): Protected caller Thread ID is 7561
2021-11-17T18:06:53.826Z,1637172413.826 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2021-11-17T18:06:53.827Z,1637172413.827 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2021-11-17T18:06:53.827Z,1637172413.827 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 7562
2021-11-17T18:06:53.839Z,1637172413.839 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2021-11-17T18:06:53.865Z,1637172413.865 [ComponentRegistry](DEBUG): Component "CommandExec" handled in its own thread.
2021-11-17T18:06:53.866Z,1637172413.866 [CommandExec ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2021-11-17T18:06:53.866Z,1637172413.866 [CommandExec ThreadHandler](INFO): Protected caller Thread ID is 7563
2021-11-17T18:06:53.871Z,1637172413.871 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2021-11-17T18:06:53.872Z,1637172413.872 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2021-11-17T18:06:53.872Z,1637172413.872 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 7564
2021-11-17T18:06:53.874Z,1637172413.874 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2021-11-17T18:06:53.884Z,1637172413.884 [logger ThreadHandler](DEBUG): Created PCaller Thread at 405114E0
2021-11-17T18:06:53.884Z,1637172413.884 [logger ThreadHandler](INFO): Protected caller Thread ID is 7565
2021-11-17T18:06:53.888Z,1637172413.888 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2021-11-17T18:06:53.888Z,1637172413.888 [Supervisor](INFO): Looking for Config files in directory: Config/
2021-11-17T18:06:53.890Z,1637172413.890 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2021-11-17T18:06:54.226Z,1637172414.226 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2021-11-17T18:06:54.227Z,1637172414.227 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2021-11-17T18:06:54.342Z,1637172414.342 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2021-11-17T18:06:55.090Z,1637172415.090 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2021-11-17T18:06:55.091Z,1637172415.091 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2021-11-17T18:06:55.576Z,1637172415.576 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2021-11-17T18:06:55.576Z,1637172415.576 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2021-11-17T18:06:55.854Z,1637172415.854 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2021-11-17T18:06:55.855Z,1637172415.855 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2021-11-17T18:06:56.387Z,1637172416.387 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2021-11-17T18:06:56.388Z,1637172416.388 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2021-11-17T18:06:56.674Z,1637172416.674 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2021-11-17T18:06:56.675Z,1637172416.675 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2021-11-17T18:06:57.528Z,1637172417.528 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2021-11-17T18:06:57.528Z,1637172417.528 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2021-11-17T18:06:57.742Z,1637172417.742 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2021-11-17T18:06:57.743Z,1637172417.743 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2021-11-17T18:06:57.830Z,1637172417.830 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2021-11-17T18:06:58.479Z,1637172418.479 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2021-11-17T18:06:58.480Z,1637172418.480 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2021-11-17T18:06:58.829Z,1637172418.829 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2021-11-17T18:06:58.829Z,1637172418.829 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2021-11-17T18:06:59.013Z,1637172419.013 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2021-11-17T18:06:59.014Z,1637172419.014 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2021-11-17T18:06:59.123Z,1637172419.123 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2021-11-17T18:06:59.123Z,1637172419.123 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2021-11-17T18:06:59.271Z,1637172419.271 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2021-11-17T18:06:59.272Z,1637172419.272 [Supervisor](INFO): Opening Config file at: Config/Dock.cfg
2021-11-17T18:06:59.492Z,1637172419.492 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Dock
2021-11-17T18:06:59.493Z,1637172419.493 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2021-11-17T18:06:59.494Z,1637172419.494 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg
2021-11-17T18:06:59.584Z,1637172419.584 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2021-11-17T18:06:59.668Z,1637172419.668 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2021-11-17T18:06:59.768Z,1637172419.768 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg
2021-11-17T18:06:59.850Z,1637172419.850 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2021-11-17T18:06:59.943Z,1637172419.943 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2021-11-17T18:07:00.042Z,1637172420.042 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2021-11-17T18:07:00.220Z,1637172420.220 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg
2021-11-17T18:07:00.296Z,1637172420.296 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2021-11-17T18:07:00.439Z,1637172420.439 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2021-11-17T18:07:00.572Z,1637172420.572 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2021-11-17T18:07:00.974Z,1637172420.974 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Battery.cfg
2021-11-17T18:07:01.567Z,1637172421.567 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2021-11-17T18:07:01.657Z,1637172421.657 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/root/
2021-11-17T18:07:01.658Z,1637172421.658 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2021-11-17T18:07:01.669Z,1637172421.669 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2021-11-17T18:07:01.726Z,1637172421.726 [VerticalControl](DEBUG): Construct VerticalControl.
2021-11-17T18:07:01.789Z,1637172421.789 [VerticalControl] Loaded
2021-11-17T18:07:01.789Z,1637172421.789 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2021-11-17T18:07:01.792Z,1637172421.792 [HorizontalControl](DEBUG): Construct HorizontalControl.
2021-11-17T18:07:01.830Z,1637172421.830 [HorizontalControl] Loaded
2021-11-17T18:07:01.830Z,1637172421.830 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2021-11-17T18:07:01.833Z,1637172421.833 [SpeedControl](DEBUG): Construct SpeedControl.
2021-11-17T18:07:01.836Z,1637172421.836 [SpeedControl] Loaded
2021-11-17T18:07:01.836Z,1637172421.836 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2021-11-17T18:07:01.839Z,1637172421.839 [LoopControl](DEBUG): Construct LoopControl.
2021-11-17T18:07:01.839Z,1637172421.839 [LoopControl] Loaded
2021-11-17T18:07:01.839Z,1637172421.839 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2021-11-17T18:07:01.840Z,1637172421.840 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2021-11-17T18:07:01.840Z,1637172421.840 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2021-11-17T18:07:01.851Z,1637172421.851 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2021-11-17T18:07:01.852Z,1637172421.852 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2021-11-17T18:07:01.957Z,1637172421.957 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2021-11-17T18:07:01.958Z,1637172421.958 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2021-11-17T18:07:02.112Z,1637172422.112 [BuoyancyServo] Loaded
2021-11-17T18:07:02.112Z,1637172422.112 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2021-11-17T18:07:02.131Z,1637172422.131 [ElevatorServo] Loaded
2021-11-17T18:07:02.131Z,1637172422.131 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2021-11-17T18:07:02.150Z,1637172422.150 [MassServo] Loaded
2021-11-17T18:07:02.150Z,1637172422.150 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2021-11-17T18:07:02.168Z,1637172422.168 [RudderServo] Loaded
2021-11-17T18:07:02.168Z,1637172422.168 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2021-11-17T18:07:02.186Z,1637172422.186 [ThrusterServo] Loaded
2021-11-17T18:07:02.186Z,1637172422.186 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2021-11-17T18:07:02.187Z,1637172422.187 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2021-11-17T18:07:02.188Z,1637172422.188 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2021-11-17T18:07:02.270Z,1637172422.270 [DeadReckonUsingMultipleVelocitySources] Loaded
2021-11-17T18:07:02.270Z,1637172422.270 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2021-11-17T18:07:02.283Z,1637172422.283 [NavChart] Loaded
2021-11-17T18:07:02.283Z,1637172422.283 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2021-11-17T18:07:02.289Z,1637172422.289 [UniversalFixResidualReporter] Loaded
2021-11-17T18:07:02.289Z,1637172422.289 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2021-11-17T18:07:02.290Z,1637172422.290 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2021-11-17T18:07:02.290Z,1637172422.290 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2021-11-17T18:07:02.350Z,1637172422.350 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2021-11-17T18:07:02.351Z,1637172422.351 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2021-11-17T18:07:02.742Z,1637172422.742 [AHRS_M2] Loaded
2021-11-17T18:07:02.742Z,1637172422.742 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2021-11-17T18:07:03.541Z,1637172423.541 [BPC1] Loaded
2021-11-17T18:07:03.542Z,1637172423.542 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2021-11-17T18:07:03.615Z,1637172423.615 [DataOverHttps] Loaded
2021-11-17T18:07:03.615Z,1637172423.615 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2021-11-17T18:07:03.616Z,1637172423.616 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 408C64E0
2021-11-17T18:07:03.617Z,1637172423.617 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 7650
2021-11-17T18:07:03.637Z,1637172423.637 [Depth_Keller] Loaded
2021-11-17T18:07:03.637Z,1637172423.637 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2021-11-17T18:07:03.642Z,1637172423.642 [DropWeight] Loaded
2021-11-17T18:07:03.642Z,1637172423.642 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2021-11-17T18:07:03.702Z,1637172423.702 [NAL9602] Loaded
2021-11-17T18:07:03.702Z,1637172423.702 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2021-11-17T18:07:03.732Z,1637172423.732 [Onboard] Loaded
2021-11-17T18:07:03.732Z,1637172423.732 [ComponentRegistry](DEBUG): Component "Onboard" handled in its own thread.
2021-11-17T18:07:03.733Z,1637172423.733 [Onboard ThreadHandler](DEBUG): Created PCaller Thread at 408F64E0
2021-11-17T18:07:03.733Z,1637172423.733 [Onboard ThreadHandler](INFO): Protected caller Thread ID is 7651
2021-11-17T18:07:03.746Z,1637172423.746 [Power24vConverter] Loaded
2021-11-17T18:07:03.747Z,1637172423.747 [ComponentRegistry](DEBUG): SyncComponent "Power24vConverter" handled in the control thread.
2021-11-17T18:07:03.760Z,1637172423.760 [Radio_Surface] Loaded
2021-11-17T18:07:03.760Z,1637172423.760 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2021-11-17T18:07:03.761Z,1637172423.761 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 409264E0
2021-11-17T18:07:03.762Z,1637172423.762 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 7652
2021-11-17T18:07:03.844Z,1637172423.844 [DAT] Loaded
2021-11-17T18:07:03.844Z,1637172423.844 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread.
2021-11-17T18:07:03.844Z,1637172423.844 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2021-11-17T18:07:03.845Z,1637172423.845 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2021-11-17T18:07:03.888Z,1637172423.888 [DepthRateCalculator] Loaded
2021-11-17T18:07:03.889Z,1637172423.889 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2021-11-17T18:07:03.893Z,1637172423.893 [PitchRateCalculator] Loaded
2021-11-17T18:07:03.894Z,1637172423.894 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2021-11-17T18:07:03.903Z,1637172423.903 [SpeedCalculator] Loaded
2021-11-17T18:07:03.903Z,1637172423.903 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2021-11-17T18:07:03.917Z,1637172423.917 [TempGradientCalculator] Loaded
2021-11-17T18:07:03.917Z,1637172423.917 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2021-11-17T18:07:03.922Z,1637172423.922 [YawRateCalculator] Loaded
2021-11-17T18:07:03.922Z,1637172423.922 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2021-11-17T18:07:03.940Z,1637172423.940 [ElevatorOffsetCalculator] Loaded
2021-11-17T18:07:03.940Z,1637172423.940 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2021-11-17T18:07:03.940Z,1637172423.940 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2021-11-17T18:07:03.941Z,1637172423.941 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2021-11-17T18:07:04.078Z,1637172424.078 [CANONSampler] Loaded
2021-11-17T18:07:04.079Z,1637172424.079 [ComponentRegistry](DEBUG): SyncComponent "CANONSampler" handled in the control thread.
2021-11-17T18:07:04.138Z,1637172424.138 [CTD_Seabird] Loaded
2021-11-17T18:07:04.138Z,1637172424.138 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread.
2021-11-17T18:07:04.139Z,1637172424.139 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 409DB4E0
2021-11-17T18:07:04.139Z,1637172424.139 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 7653
2021-11-17T18:07:04.159Z,1637172424.159 [PAR_Licor] Loaded
2021-11-17T18:07:04.159Z,1637172424.159 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2021-11-17T18:07:04.192Z,1637172424.192 [WetLabsBB2FL] Loaded
2021-11-17T18:07:04.192Z,1637172424.192 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2021-11-17T18:07:04.193Z,1637172424.193 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 40A0B4E0
2021-11-17T18:07:04.193Z,1637172424.193 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 7654
2021-11-17T18:07:04.194Z,1637172424.194 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2021-11-17T18:07:04.195Z,1637172424.195 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2021-11-17T18:07:04.223Z,1637172424.223 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2021-11-17T18:07:04.224Z,1637172424.224 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2021-11-17T18:07:04.553Z,1637172424.553 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2021-11-17T18:07:04.553Z,1637172424.553 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2021-11-17T18:07:04.702Z,1637172424.702 [SBIT](DEBUG): Construct Startup Built In Test.
2021-11-17T18:07:04.711Z,1637172424.711 [SBIT] Loaded
2021-11-17T18:07:04.712Z,1637172424.712 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2021-11-17T18:07:04.714Z,1637172424.714 [IBIT](DEBUG): Construct Initiated Built In Test.
2021-11-17T18:07:04.728Z,1637172424.728 [IBIT] Loaded
2021-11-17T18:07:04.728Z,1637172424.728 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2021-11-17T18:07:04.734Z,1637172424.734 [CBIT](DEBUG): Construct Continuous Built In Test.
2021-11-17T18:07:04.837Z,1637172424.837 [CBIT] Loaded
2021-11-17T18:07:04.837Z,1637172424.837 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2021-11-17T18:07:04.838Z,1637172424.838 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2021-11-17T18:07:04.838Z,1637172424.838 [Module Loader](DEBUG): Loading Module at Modules/Dock.so
2021-11-17T18:07:04.935Z,1637172424.935 [Module Loader](DEBUG): Loaded Module: Dock (Contains behaviors and commands for docking)
2021-11-17T18:07:04.941Z,1637172424.941 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2021-11-17T18:07:04.944Z,1637172424.944 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2021-11-17T18:07:04.955Z,1637172424.955 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2021-11-17T18:07:04.956Z,1637172424.956 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40B404E0
2021-11-17T18:07:04.956Z,1637172424.956 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 7655
2021-11-17T18:07:04.961Z,1637172424.961 [Supervisor](INFO): Main Thread ID is 6245
2021-11-17T18:07:04.961Z,1637172424.961 [Supervisor](DEBUG): Running supervisor.
2021-11-17T18:07:04.962Z,1637172424.962 [CommandExec ThreadHandler](INFO): Handler Thread ID is 7656
2021-11-17T18:07:04.962Z,1637172424.962 [CommandExec](INFO): Initializing the command executive.
2021-11-17T18:07:04.964Z,1637172424.964 [CommandLine ThreadHandler](INFO): Handler Thread ID is 7657
2021-11-17T18:07:04.966Z,1637172424.966 [controlThread ThreadHandler](INFO): Handler Thread ID is 7658
2021-11-17T18:07:04.967Z,1637172424.967 [controlThread](DEBUG): Initializing ControlThread
2021-11-17T18:07:04.967Z,1637172424.967 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2021-11-17T18:07:04.969Z,1637172424.969 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2021-11-17T18:07:04.970Z,1637172424.970 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2021-11-17T18:07:04.971Z,1637172424.971 [LoopControl](DEBUG): Initialize LoopControlComponent.
2021-11-17T18:07:04.972Z,1637172424.972 [NavChart](DEBUG): Initialize NavChart Navigation.
2021-11-17T18:07:04.973Z,1637172424.973 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2021-11-17T18:07:04.977Z,1637172424.977 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2021-11-17T18:07:04.978Z,1637172424.978 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2021-11-17T18:07:04.978Z,1637172424.978 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2021-11-17T18:07:04.978Z,1637172424.978 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2021-11-17T18:07:04.979Z,1637172424.979 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2021-11-17T18:07:04.980Z,1637172424.980 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2021-11-17T18:07:04.984Z,1637172424.984 [SBIT](INFO): Initialize SBIT Component.
2021-11-17T18:07:04.984Z,1637172424.984 [SBIT](IMPORTANT): git: 2021-10-11a
2021-11-17T18:07:04.984Z,1637172424.984 [SBIT](INFO): git hash: 36f3a97de7a122c995f034a375e3cefac6406048
2021-11-17T18:07:04.985Z,1637172424.985 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2021-11-17T18:07:04.986Z,1637172424.986 [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-17T18:07:04.988Z,1637172424.988 [logger ThreadHandler](INFO): Handler Thread ID is 7659
2021-11-17T18:07:05.003Z,1637172425.003 [SBIT](INFO): Beginning SBIT in 84.000000 seconds.
2021-11-17T18:07:05.004Z,1637172425.004 [IBIT](INFO): Initialize IBIT Component.
2021-11-17T18:07:05.005Z,1637172425.005 [CBIT](DEBUG): Initialize CBIT Component.
2021-11-17T18:07:05.012Z,1637172425.012 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 7660
2021-11-17T18:07:05.013Z,1637172425.013 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2021-11-17T18:07:05.016Z,1637172425.016 [CBIT](DEBUG): Initialized mux pins.
2021-11-17T18:07:05.016Z,1637172425.016 [CBIT](DEBUG): Initializing the watchdog timer.
2021-11-17T18:07:05.024Z,1637172425.024 [Onboard ThreadHandler](INFO): Handler Thread ID is 7661
2021-11-17T18:07:05.039Z,1637172425.039 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2021-11-17T18:07:05.040Z,1637172425.040 [CBIT](DEBUG): Initializing heartbeat.
2021-11-17T18:07:05.043Z,1637172425.043 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 7662
2021-11-17T18:07:05.060Z,1637172425.060 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 7663
2021-11-17T18:07:05.060Z,1637172425.060 [CTD_Seabird](DEBUG): Initializing CTD_Seabird.
2021-11-17T18:07:05.065Z,1637172425.065 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 7665
2021-11-17T18:07:05.068Z,1637172425.068 [WetLabsBB2FL](INFO): Powering up
2021-11-17T18:07:05.070Z,1637172425.070 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 7667
2021-11-17T18:07:05.073Z,1637172425.073 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2021-11-17T18:07:05.073Z,1637172425.073 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2021-11-17T18:07:05.073Z,1637172425.073 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2021-11-17T18:07:05.074Z,1637172425.074 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2021-11-17T18:07:05.074Z,1637172425.074 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2021-11-17T18:07:05.074Z,1637172425.074 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2021-11-17T18:07:05.074Z,1637172425.074 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2021-11-17T18:07:05.074Z,1637172425.074 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2021-11-17T18:07:05.074Z,1637172425.074 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2021-11-17T18:07:05.075Z,1637172425.075 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2021-11-17T18:07:05.075Z,1637172425.075 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2021-11-17T18:07:05.075Z,1637172425.075 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2021-11-17T18:07:05.076Z,1637172425.076 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2021-11-17T18:07:05.076Z,1637172425.076 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2021-11-17T18:07:05.076Z,1637172425.076 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2021-11-17T18:07:05.076Z,1637172425.076 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2021-11-17T18:07:05.111Z,1637172425.111 [CBIT](DEBUG): Deactivating GF circuits.
2021-11-17T18:07:05.112Z,1637172425.112 [CBIT](DEBUG): Deactivating emergency mode.
2021-11-17T18:07:05.147Z,1637172425.147 [CBIT](DEBUG): Backplane powered.
2021-11-17T18:07:05.148Z,1637172425.148 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2021-11-17T18:07:05.161Z,1637172425.161 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2021-11-17T18:07:05.189Z,1637172425.189 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Guidance="Tethys/Guidance" 
       xmlns:Units="Tethys/Units"
       xmlns:Universal="Tethys/Universal"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                           Tethys/Control http://okeanids.mbari.org/tethys/Xml/Control.xsd
                           Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                           Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                           Tethys/Universal http://okeanids.mbari.org/tethys/Xml/Universal.xsd"
       Id="Startup">

    <Guidance:GoToSurface>
        <Progression/>
    </Guidance:GoToSurface>

    <Aggregate Id="StartupSatComms">

        <Sequence/>

        <ReadDatum>
            <Timeout Duration="P1M" />
            <Universal:latitude_fix/>
        </ReadDatum>

        <ReadDatum>
            <Timeout Duration="P1M" />
            <Universal:platform_communications/>
        </ReadDatum>

    </Aggregate>

</Mission>


2021-11-17T18:07:05.190Z,1637172425.190 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2021-11-17T18:07:05.269Z,1637172425.269 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2021-11-17T18:07:05.270Z,1637172425.270 [Default:A.Wait](DEBUG): Construct Wait.
2021-11-17T18:07:05.284Z,1637172425.284 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2021-11-17T18:07:05.316Z,1637172425.316 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2021-11-17T18:07:05.319Z,1637172425.319 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2021-11-17T18:07:05.341Z,1637172425.341 [Default:E.Execute](DEBUG): Construct Execute.
2021-11-17T18:07:05.355Z,1637172425.355 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Universal="Tethys/Universal"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                             Tethys/Universal http://okeanids.mbari.org/tethys/Xml/Universal.xsd"
         Id="Default">

    <DefineArg Name="ElapsedSinceDefaultStarted"><Units:minute/><Value>0</Value></DefineArg>

    <Guidance:Wait>
        <Description>
            Wait a moment to see if the scheduler starts a new mission before
            starting to actually run Default.
        </Description>
        <Sequence/>
        <Setting><Guidance:Wait.duration/><Units:second/><Value>13</Value></Setting>
    </Guidance:Wait>

    <Guidance:GoToSurface>
        <Progression/>
    </Guidance:GoToSurface>

    <Aggregate Id="CheckIn">

        <Sequence Repeat="288"/>

        <ReadDatum Id="Read_GPS">
            <Timeout Duration="P1M"/>
            <Universal:time_fix/>
        </ReadDatum>

        <ReadDatum Id="Read_Iridium">
            <Timeout Duration="P2H">
                <Guidance:Execute>
                    <Sequence/>
                    <Setting><Guidance:Execute.command/><String>Burn on</String></Setting>
                </Guidance:Execute>
                <Syslog Severity="Critical">Dropped weight due to communications timeout.</Syslog>
            </Timeout>
            <Universal:platform_communications/>
        </ReadDatum>

        <Guidance:Wait>
            <Sequence/>
            <Setting><Guidance:Wait.duration/><Units:minute/><Value>1</Value></Setting>
        </Guidance:Wait>

        <Assign><Sequence/><Arg Name="ElapsedSinceDefaultStarted"/><Elapsed><Universal:mission_started/></Elapsed></Assign>

        <Syslog Severity="Important">Default mission has been running for <Arg Name="ElapsedSinceDefaultStarted"/><Units:minute/></Syslog>

    </Aggregate>

    <Syslog Severity="Important">Restarting logs and Default mission.</Syslog>

    <Guidance:Execute>
        <Sequence/>
        <Setting><Guidance:Execute.command/><String>restart logs</String></Setting>
    </Guidance:Execute>

</Mission>


2021-11-17T18:07:05.368Z,1637172425.368 [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-17T18:07:05.375Z,1637172425.375 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2021-11-17T18:07:05.448Z,1637172425.448 [Radio_Surface](INFO): Powering up
2021-11-17T18:07:05.460Z,1637172425.460 [Depth_Keller](ERROR): Pressure reading out of range: 915.616455 decibar
2021-11-17T18:07:05.461Z,1637172425.461 [Power24vConverter](INFO): Powering up.
2021-11-17T18:07:05.462Z,1637172425.462 [DAT](INFO): Powering up
2021-11-17T18:07:05.462Z,1637172425.462 [DAT](DEBUG): Initializing DAT.
2021-11-17T18:07:05.480Z,1637172425.480 [CANONSampler](INFO): Powering down
2021-11-17T18:07:05.500Z,1637172425.500 [DepthRateCalculator](ERROR): Depth measurement is not active
2021-11-17T18:07:05.521Z,1637172425.521 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2021-11-17T18:07:05.532Z,1637172425.532 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2021-11-17T18:07:05.533Z,1637172425.533 [ElevatorServo](DEBUG): Initializing EZServoServo.
2021-11-17T18:07:05.540Z,1637172425.540 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2021-11-17T18:07:05.541Z,1637172425.541 [MassServo](DEBUG): Initializing EZServoServo.
2021-11-17T18:07:05.552Z,1637172425.552 [MassServo](DEBUG): Initializing MassServo.
2021-11-17T18:07:05.553Z,1637172425.553 [RudderServo](DEBUG): Initializing EZServoServo.
2021-11-17T18:07:05.560Z,1637172425.560 [RudderServo](DEBUG): Initializing RudderServo.
2021-11-17T18:07:05.561Z,1637172425.561 [ThrusterServo](DEBUG): Initializing EZServoServo.
2021-11-17T18:07:05.568Z,1637172425.568 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2021-11-17T18:07:05.801Z,1637172425.801 [DropWeight](CRITICAL): DROP WEIGHT MISSING.

2021-11-17T18:07:05.802Z,1637172425.802 [DropWeight] Hardware Fault, FailCount= 1
2021-11-17T18:07:05.802Z,1637172425.802 [DropWeight](ERROR): Hardware Fault
2021-11-17T18:07:05.831Z,1637172425.831 [CommandExec](FAULT): Scheduling is paused
2021-11-17T18:07:05.832Z,1637172425.832 [CBIT](INFO): Critical error at 20211117T180705
2021-11-17T18:07:05.832Z,1637172425.832 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals
2021-11-17T18:07:05.834Z,1637172425.834 [CBIT](ERROR): Hardware Fault in component: DropWeight
2021-11-17T18:07:05.835Z,1637172425.835 [CBIT](CRITICAL): Hardware Fault in component: DropWeight
2021-11-17T18:07:06.515Z,1637172426.515 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2021-11-17T18:07:06.516Z,1637172426.516 [RudderServo](FAULT): Rudder failed to initialize
2021-11-17T18:07:06.516Z,1637172426.516 [RudderServo] Communications Fault, FailCount= 1
2021-11-17T18:07:06.516Z,1637172426.516 [RudderServo](ERROR): Communications Fault
2021-11-17T18:07:06.617Z,1637172426.617 [CBIT](INFO): Critical error at 20211117T180705
2021-11-17T18:07:06.619Z,1637172426.619 [CBIT](ERROR): Communications Fault in component: RudderServo
2021-11-17T18:07:06.809Z,1637172426.809 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2021-11-17T18:07:06.809Z,1637172426.809 [RudderServo](INFO): Powering down
2021-11-17T18:07:07.175Z,1637172427.175 [WetLabsBB2FL](INFO): Powering down
2021-11-17T18:07:07.461Z,1637172427.461 [RudderServo](DEBUG): Initializing EZServoServo.
2021-11-17T18:07:07.580Z,1637172427.580 [RudderServo](DEBUG): Initializing RudderServo.
2021-11-17T18:07:07.585Z,1637172427.585 [CBIT](INFO): Clearing failed state for component RudderServo
2021-11-17T18:07:07.585Z,1637172427.585 [RudderServo] No Fault, FailCount= 1
2021-11-17T18:07:17.141Z,1637172437.141 [DAT](INFO): DAT read: 

2021-11-17T18:07:17.143Z,1637172437.143 [DAT](INFO): DAT read: Teledyne Benthos DAT-900 Series

2021-11-17T18:07:18.754Z,1637172438.754 [DAT](INFO): DAT read: MF Frequency Band

2021-11-17T18:07:18.755Z,1637172438.755 [DAT](INFO): DAT read: Directional Acoustic Transponder version 8.14.2

2021-11-17T18:07:18.756Z,1637172438.756 [DAT](INFO): DAT read: Nov 17 2021 18:06:38 

2021-11-17T18:07:19.966Z,1637172439.966 [DAT](INFO): DAT read: Features enabled [Bearing]

2021-11-17T18:07:19.967Z,1637172439.967 [DAT](INFO): DAT read: CONNECT 00800 bits/sec 1 of 4, Rate 1/2 CC 12.50ms MGP

2021-11-17T18:07:19.968Z,1637172439.968 [DAT](INFO): commRate: 800
2021-11-17T18:07:21.986Z,1637172441.986 [DAT](INFO): entering command mode
2021-11-17T18:07:22.389Z,1637172442.389 [DAT](INFO): DAT read: 

2021-11-17T18:07:22.390Z,1637172442.390 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T18:07:22.793Z,1637172442.793 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T18:07:23.197Z,1637172443.197 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T18:07:23.601Z,1637172443.601 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T18:07:24.005Z,1637172444.005 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T18:07:24.409Z,1637172444.409 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T18:07:24.813Z,1637172444.813 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T18:07:25.217Z,1637172445.217 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T18:07:25.621Z,1637172445.621 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T18:07:26.029Z,1637172446.029 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T18:07:26.429Z,1637172446.429 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T18:07:26.833Z,1637172446.833 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T18:07:27.241Z,1637172447.241 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T18:07:27.641Z,1637172447.641 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T18:07:28.045Z,1637172448.045 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T18:07:28.449Z,1637172448.449 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T18:07:28.857Z,1637172448.857 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T18:07:29.257Z,1637172449.257 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T18:07:29.661Z,1637172449.661 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T18:07:30.065Z,1637172450.065 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T18:07:30.478Z,1637172450.478 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T18:07:30.873Z,1637172450.873 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T18:07:31.278Z,1637172451.278 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T18:07:31.681Z,1637172451.681 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T18:07:32.092Z,1637172452.092 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T18:07:32.489Z,1637172452.489 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T18:07:32.893Z,1637172452.893 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T18:07:33.297Z,1637172453.297 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T18:07:33.709Z,1637172453.709 [NAL9602](INFO): Powering up NAL9602
2021-11-17T18:07:33.711Z,1637172453.711 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T18:07:34.105Z,1637172454.105 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T18:07:34.509Z,1637172454.509 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T18:07:34.913Z,1637172454.913 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T18:07:35.318Z,1637172455.318 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T18:07:35.721Z,1637172455.721 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T18:07:36.125Z,1637172456.125 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T18:07:36.529Z,1637172456.529 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T18:07:36.933Z,1637172456.933 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T18:07:37.350Z,1637172457.350 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T18:07:37.350Z,1637172457.350 [DAT](FAULT): failed to enter command mode
2021-11-17T18:07:37.741Z,1637172457.741 [DAT](INFO): entering command mode
2021-11-17T18:07:38.145Z,1637172458.145 [DAT](INFO): DAT read: user:1>

2021-11-17T18:07:38.146Z,1637172458.146 [DAT](INFO): DAT read: Command '+++' not found

2021-11-17T18:07:38.147Z,1637172458.147 [DAT](INFO): DAT read: Error

2021-11-17T18:07:38.147Z,1637172458.147 [DAT](INFO): setting verbose to 3
2021-11-17T18:07:38.550Z,1637172458.550 [DAT](INFO): DAT read: user:2>

2021-11-17T18:07:38.551Z,1637172458.551 [DAT](INFO): DAT read: Verbose         | 3           

2021-11-17T18:07:38.551Z,1637172458.551 [DAT](INFO): set verbose to 3
2021-11-17T18:07:38.551Z,1637172458.551 [DAT](INFO): setting DatVerbose to 27440
2021-11-17T18:07:38.953Z,1637172458.953 [DAT](INFO): DAT read: user:3>

2021-11-17T18:07:38.954Z,1637172458.954 [DAT](INFO): DAT read: DatVerbose      | 27440       

2021-11-17T18:07:38.955Z,1637172458.955 [DAT](INFO): set DatVerbose to 27440
2021-11-17T18:07:38.955Z,1637172458.955 [DAT](INFO): setting transmit power to 8
2021-11-17T18:07:39.358Z,1637172459.358 [DAT](INFO): DAT read: user:4>

2021-11-17T18:07:39.359Z,1637172459.359 [DAT](INFO): DAT read: TxPower         | 8 (Max)     

2021-11-17T18:07:39.359Z,1637172459.359 [DAT](INFO): set transmit power to 8
2021-11-17T18:07:39.359Z,1637172459.359 [DAT](INFO): setting local address to 7
2021-11-17T18:07:39.762Z,1637172459.762 [DAT](INFO): DAT read: user:5>

2021-11-17T18:07:39.763Z,1637172459.763 [DAT](INFO): DAT read: LocalAddr       | 7           

2021-11-17T18:07:39.763Z,1637172459.763 [DAT](INFO): set local address to 7
2021-11-17T18:07:44.535Z,1637172464.535 [CommandExec](IMPORTANT): got command maintain sensor NAL9602.latitude_fix 36.799999 degree
2021-11-17T18:07:44.542Z,1637172464.542 [ComponentRegistry](DEBUG): SyncComponent "Maintain_NAL9602.latitude_fix" handled in the control thread.
2021-11-17T18:07:44.543Z,1637172464.543 [CommandExec](IMPORTANT): got command maintain sensor NAL9602.longitude_fix -121.900002 degree
2021-11-17T18:07:44.580Z,1637172464.580 [ComponentRegistry](DEBUG): SyncComponent "Maintain_NAL9602.longitude_fix" handled in the control thread.
2021-11-17T18:07:44.622Z,1637172464.622 [NAL9602](INFO): NAL9602 initialized
2021-11-17T18:07:44.691Z,1637172464.691 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,BPC1,Depth_Keller,DropWeight,NAL9602,Power24vConverter,DAT,CANONSampler,PAR_Licor,Depth_Keller,PAR_Licor,Maintain_NAL9602.latitude_fix,Maintain_NAL9602.longitude_fix,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2021-11-17T18:07:45.049Z,1637172465.049 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2021-11-17T18:07:45.049Z,1637172465.049 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2021-11-17T18:07:45.050Z,1637172465.050 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-11-17T18:07:45.132Z,1637172465.132 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-11-17T18:07:45.508Z,1637172465.508 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-11-17T18:07:45.508Z,1637172465.508 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2021-11-17T18:07:46.282Z,1637172466.282 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2021-11-17T18:07:46.282Z,1637172466.282 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2
2021-11-17T18:07:46.282Z,1637172466.282 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-11-17T18:07:46.353Z,1637172466.353 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-11-17T18:07:46.708Z,1637172466.708 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-11-17T18:07:46.709Z,1637172466.709 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2
2021-11-17T18:07:47.464Z,1637172467.464 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2021-11-17T18:07:47.465Z,1637172467.465 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 3
2021-11-17T18:07:47.465Z,1637172467.465 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-11-17T18:07:47.544Z,1637172467.544 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-11-17T18:07:47.936Z,1637172467.936 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-11-17T18:07:47.936Z,1637172467.936 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 3
2021-11-17T18:07:48.717Z,1637172468.717 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2021-11-17T18:07:48.717Z,1637172468.717 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 4
2021-11-17T18:07:48.717Z,1637172468.717 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-11-17T18:07:48.785Z,1637172468.785 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-11-17T18:07:49.108Z,1637172469.108 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-11-17T18:07:49.108Z,1637172469.108 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 4
2021-11-17T18:07:49.906Z,1637172469.906 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2021-11-17T18:07:49.906Z,1637172469.906 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 5
2021-11-17T18:07:49.906Z,1637172469.906 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-11-17T18:07:49.968Z,1637172469.968 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-11-17T18:07:50.348Z,1637172470.348 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-11-17T18:07:50.348Z,1637172470.348 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 5
2021-11-17T18:07:51.100Z,1637172471.100 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2021-11-17T18:07:51.101Z,1637172471.101 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 6
2021-11-17T18:07:51.101Z,1637172471.101 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-11-17T18:07:51.196Z,1637172471.196 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-11-17T18:07:51.556Z,1637172471.556 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-11-17T18:07:51.556Z,1637172471.556 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 6
2021-11-17T18:07:52.328Z,1637172472.328 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2021-11-17T18:07:52.328Z,1637172472.328 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 7
2021-11-17T18:07:52.328Z,1637172472.328 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-11-17T18:07:52.403Z,1637172472.403 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-11-17T18:07:52.784Z,1637172472.784 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-11-17T18:07:52.784Z,1637172472.784 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 7
2021-11-17T18:07:53.545Z,1637172473.545 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2021-11-17T18:07:53.545Z,1637172473.545 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 8
2021-11-17T18:07:53.545Z,1637172473.545 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-11-17T18:07:53.555Z,1637172473.555 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-11-17T18:07:53.973Z,1637172473.973 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-11-17T18:07:53.973Z,1637172473.973 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 8
2021-11-17T18:07:54.738Z,1637172474.738 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2021-11-17T18:07:54.738Z,1637172474.738 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 9
2021-11-17T18:07:54.738Z,1637172474.738 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-11-17T18:07:54.749Z,1637172474.749 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-11-17T18:07:55.163Z,1637172475.163 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-11-17T18:07:55.163Z,1637172475.163 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 9
2021-11-17T18:07:55.946Z,1637172475.946 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2021-11-17T18:07:55.946Z,1637172475.946 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 10
2021-11-17T18:07:55.946Z,1637172475.946 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-11-17T18:07:55.992Z,1637172475.992 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-11-17T18:07:56.367Z,1637172476.367 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-11-17T18:07:56.371Z,1637172476.371 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 10
2021-11-17T18:07:57.171Z,1637172477.171 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2021-11-17T18:07:57.171Z,1637172477.171 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 11
2021-11-17T18:07:57.171Z,1637172477.171 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-11-17T18:07:57.189Z,1637172477.189 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-11-17T18:07:57.596Z,1637172477.596 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-11-17T18:07:57.596Z,1637172477.596 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 11
2021-11-17T18:07:58.385Z,1637172478.385 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2021-11-17T18:07:58.385Z,1637172478.385 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 12
2021-11-17T18:07:58.385Z,1637172478.385 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-11-17T18:07:58.449Z,1637172478.449 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-11-17T18:07:58.798Z,1637172478.798 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-11-17T18:07:58.798Z,1637172478.798 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 12
2021-11-17T18:07:59.580Z,1637172479.580 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2021-11-17T18:07:59.580Z,1637172479.580 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 13
2021-11-17T18:07:59.580Z,1637172479.580 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-11-17T18:07:59.647Z,1637172479.647 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-11-17T18:07:59.997Z,1637172479.997 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-11-17T18:07:59.998Z,1637172479.998 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 13
2021-11-17T18:08:00.802Z,1637172480.802 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2021-11-17T18:08:00.802Z,1637172480.802 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 14
2021-11-17T18:08:00.802Z,1637172480.802 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-11-17T18:08:00.827Z,1637172480.827 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-11-17T18:08:01.237Z,1637172481.237 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-11-17T18:08:01.237Z,1637172481.237 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 14
2021-11-17T18:08:01.794Z,1637172481.794 [CommandExec](IMPORTANT): got command set NAL9602.time_fix 1637172480.000000 second
2021-11-17T18:08:09.393Z,1637172489.393 [CommandExec](IMPORTANT): got command strobe off
2021-11-17T18:08:09.393Z,1637172489.393 [CommandExec](IMPORTANT): Deactivating strobe
2021-11-17T18:08:29.501Z,1637172509.501 [SBIT](IMPORTANT): Beginning Startup BIT
2021-11-17T18:08:29.506Z,1637172509.506 [CBIT](IMPORTANT): Beginning ground fault scan
2021-11-17T18:08:40.433Z,1637172520.433 [CBIT](ERROR): Ground fault scan returned out of bounds value. Re-running scan.
2021-11-17T18:08:40.843Z,1637172520.843 [CBIT](IMPORTANT): Beginning ground fault scan
2021-11-17T18:08:51.773Z,1637172531.773 [CBIT](ERROR): Ground fault scan returned out of bounds value. Re-running scan.
2021-11-17T18:08:52.153Z,1637172532.153 [CBIT](IMPORTANT): Beginning ground fault scan
2021-11-17T18:09:03.025Z,1637172543.025 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.002342
CHAN A1 (24V): 0.000469
CHAN A2 (12V): -0.002512
CHAN A3 (5V): -0.001450
CHAN B0 (3.3V): 0.000193
CHAN B1 (3.15aV): -0.000601
CHAN B2 (3.15bV): -0.000534
CHAN B3 (GND): 0.000140
OPEN: -0.000383
Full Scale: +/- 1 mA
2021-11-17T18:09:23.617Z,1637172563.617 [SBIT](IMPORTANT): SBIT PASSED
2021-11-17T18:09:23.617Z,1637172563.617 [SBIT](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2021-11-17T18:09:23.618Z,1637172563.618 [SBIT](IMPORTANT): AMEcho.loadAtStartup=0 bool;

2021-11-17T18:09:23.618Z,1637172563.618 [SBIT](IMPORTANT): BuoyancyServo.fastPumpDepth=6 meter;

2021-11-17T18:09:23.618Z,1637172563.618 [SBIT](IMPORTANT): CANONSampler.loadAtStartup=1 bool;

2021-11-17T18:09:23.618Z,1637172563.618 [SBIT](IMPORTANT): DAT.loadAtStartup=1 bool;

2021-11-17T18:09:23.618Z,1637172563.618 [SBIT](IMPORTANT): DAT.sbdAddress=1 enum;

2021-11-17T18:09:23.619Z,1637172563.619 [SBIT](IMPORTANT): DAT.surfaceThreshold=0 meter;

2021-11-17T18:09:23.619Z,1637172563.619 [SBIT](IMPORTANT): DAT.verbosity=3 count;

2021-11-17T18:09:23.619Z,1637172563.619 [SBIT](IMPORTANT): ESPComponent.loadAtStartup=0 bool;

2021-11-17T18:09:23.619Z,1637172563.619 [SBIT](IMPORTANT): ESPComponent.simulateHardware=1 bool;

2021-11-17T18:09:23.619Z,1637172563.619 [SBIT](IMPORTANT): VerticalControl.buoyancyNeutral=296 cubic_centimeter;

2021-11-17T18:09:23.620Z,1637172563.620 [SBIT](IMPORTANT): VerticalControl.massDefault=-16 millimeter;

2021-11-17T18:09:23.620Z,1637172563.620 [SBIT](IMPORTANT): VerticalControl.surfaceThreshold=2 meter;

2021-11-17T18:09:24.025Z,1637172564.025 [MissionManager](IMPORTANT): Started mission Startup
2021-11-17T18:09:24.026Z,1637172564.026 [Startup] Running Loop=1
2021-11-17T18:09:24.026Z,1637172564.026 [Startup](DEBUG): Aggregate::initialize Startup
2021-11-17T18:09:24.026Z,1637172564.026 [Startup:A.GoToSurface] Running Loop=1
2021-11-17T18:09:24.026Z,1637172564.026 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2021-11-17T18:09:24.026Z,1637172564.026 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2021-11-17T18:09:24.027Z,1637172564.027 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2021-11-17T18:09:24.032Z,1637172564.032 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2021-11-17T18:09:24.032Z,1637172564.032 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2021-11-17T18:09:24.033Z,1637172564.033 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2021-11-17T18:09:24.034Z,1637172564.034 [Startup:StartupSatComms] Running Loop=1
2021-11-17T18:09:24.034Z,1637172564.034 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2021-11-17T18:09:24.035Z,1637172564.035 [Startup:StartupSatComms:A] Running Loop=1
2021-11-17T18:09:24.447Z,1637172564.447 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2021-11-17T18:09:24.447Z,1637172564.447 [Startup:StartupSatComms:A] Stopped
2021-11-17T18:09:24.447Z,1637172564.447 [Startup:StartupSatComms:B] Running Loop=1
2021-11-17T18:09:24.822Z,1637172564.822 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2021-11-17T18:09:25.689Z,1637172565.689 [DAT](INFO): #Outgoing data=1
2021-11-17T18:09:25.689Z,1637172565.689 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-17T18:09:25.788Z,1637172565.788 [DAT](INFO): setting remote address to 1
2021-11-17T18:09:26.135Z,1637172566.135 [DAT](INFO): DAT read: user:6>

2021-11-17T18:09:26.136Z,1637172566.136 [DAT](INFO): DAT read: RemoteAddr      | 1           

2021-11-17T18:09:26.136Z,1637172566.136 [DAT](INFO): set remote address to 1
2021-11-17T18:09:26.137Z,1637172566.137 [DAT](INFO): entering online mode
2021-11-17T18:09:26.555Z,1637172566.555 [DAT](INFO): DAT read: user:7>

2021-11-17T18:09:26.556Z,1637172566.556 [DAT](INFO): DAT read: 

2021-11-17T18:09:26.557Z,1637172566.557 [DAT](INFO): DAT read: CONNECT 00800 bits/sec 1 of 4, Rate 1/2 CC 12.50ms MGP

2021-11-17T18:09:26.557Z,1637172566.557 [DAT](INFO): commRate: 800
2021-11-17T18:09:26.557Z,1637172566.557 [DAT](INFO): online mode acknowledged
2021-11-17T18:09:26.558Z,1637172566.558 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-17T18:09:29.777Z,1637172569.777 [DAT](INFO): DAT read: Forwarding Delay UpTx time:18:08:51.7733

2021-11-17T18:09:29.777Z,1637172569.777 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-17T18:09:37.366Z,1637172577.366 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.005017
2021-11-17T18:09:37.465Z,1637172577.465 [DAT](INFO): DAT read: Rx Time:18:08:58.5455

2021-11-17T18:09:37.465Z,1637172577.465 [DAT](INFO): received an acoustic signal
2021-11-17T18:09:38.274Z,1637172578.274 [DAT](INFO): DAT read: 18:08:58.5454 LVL= 32752, 32753, 32754, 32755, AGC= 88, IDX= 231,-0.02, 2.518, 2.579, 2.525, 2.535, PHS=-0.021, 0.088,-0.026, RAW= 331.9,  -7.3, CAL= 333.0,  -9.7, ROT= 237.0,   9.7

2021-11-17T18:09:38.275Z,1637172578.275 [DAT](INFO): got valid direction response:
 18:08:58.5454 LVL= 32752, 32753, 32754, 32755, AGC= 88, IDX= 231,-0.02, 2.518, 2.579, 2.525, 2.535, PHS=-0.021, 0.088,-0.026, RAW= 331.9,  -7.3, CAL= 333.0,  -9.7, ROT= 237.0,   9.7

2021-11-17T18:09:38.276Z,1637172578.276 [DAT](INFO): DAT read: 

2021-11-17T18:09:38.277Z,1637172578.277 [DAT](INFO): DAT read: DATA(0002):~~

2021-11-17T18:09:38.277Z,1637172578.277 [DAT](INFO): Got DATA 2
2021-11-17T18:09:38.278Z,1637172578.278 [DAT](INFO): DAT read: Source:001  Destination:007

2021-11-17T18:09:38.278Z,1637172578.278 [DAT](INFO): Got Src/Dest after DATA 
2021-11-17T18:09:38.278Z,1637172578.278 [DAT](INFO): DATA Src=1, Dst=7
2021-11-17T18:09:38.280Z,1637172578.280 [DAT](INFO): DAT read: CRC:Pass MPD:03.8 PSNR:12.3 AGC:90 SPD:+0.0 CCERR:010

2021-11-17T18:09:38.280Z,1637172578.280 [DAT](INFO): Got CRC:Pass
2021-11-17T18:09:38.280Z,1637172578.280 [DAT](INFO): Got CRC:Pass
2021-11-17T18:09:38.280Z,1637172578.280 [DAT](INFO): Incoming data is intended for us
2021-11-17T18:09:38.280Z,1637172578.280 [DAT](DEBUG): In parseResponses, got ack so set commsState_ = SENDING_VERIFIED
2021-11-17T18:09:38.281Z,1637172578.281 [DAT](INFO): Got ack
2021-11-17T18:09:38.281Z,1637172578.281 [DAT](INFO): DAT read: 

2021-11-17T18:09:38.281Z,1637172578.281 [DAT](INFO): DAT read: <EOP>

2021-11-17T18:09:38.282Z,1637172578.282 [DAT](INFO): Sent 39 bytes from file Logs/20211117T175209/Courier0010.lzma.parts
2021-11-17T18:09:38.282Z,1637172578.282 [DAT](INFO): Packets left to send: 0
2021-11-17T18:09:38.285Z,1637172578.285 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-17T18:09:38.286Z,1637172578.286 [DAT](INFO): #Rx 1: Read direction message, but no range.
2021-11-17T18:09:38.305Z,1637172578.305 [DAT](INFO): direction in vehicle frame: [ -0.536853 forward, -0.826680 starboard, 0.168489 keelward ]
2021-11-17T18:09:39.417Z,1637172579.417 [DAT](INFO): #Outgoing data=1
2021-11-17T18:09:39.417Z,1637172579.417 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-17T18:09:39.526Z,1637172579.526 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-17T18:09:43.109Z,1637172583.109 [DAT](INFO): DAT read: Forwarding Delay UpTx time:18:09:04.8730

2021-11-17T18:09:43.109Z,1637172583.109 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-17T18:09:44.827Z,1637172584.827 [DataOverHttps](INFO): Sending 296 bytes from file Logs/20211117T180653/Courier0000.lzma
2021-11-17T18:09:45.829Z,1637172585.829 [DataOverHttps](INFO): Moved sent file to Logs/20211117T180653/Courier0000.lzma.bak
2021-11-17T18:09:45.829Z,1637172585.829 [DataOverHttps](INFO): SBD MOMSN=16261884
2021-11-17T18:09:51.982Z,1637172591.982 [DAT](INFO): DAT read: Rx Time:18:09:13.2958

2021-11-17T18:09:51.982Z,1637172591.982 [DAT](INFO): received an acoustic signal
2021-11-17T18:09:53.224Z,1637172593.224 [DAT](INFO): DAT read: 18:09:13.2958 LVL= 32752, 32753, 32754, 32755, AGC= 87, IDX= 188, 0.29,-1.873,-1.787,-1.860,-1.811, PHS=-0.065, 0.068,-0.064, RAW= 329.4,   9.3, CAL= 329.5,   9.3, ROT= 240.5,  -9.3

2021-11-17T18:09:53.225Z,1637172593.225 [DAT](INFO): got valid direction response:
 18:09:13.2958 LVL= 32752, 32753, 32754, 32755, AGC= 87, IDX= 188, 0.29,-1.873,-1.787,-1.860,-1.811, PHS=-0.065, 0.068,-0.064, RAW= 329.4,   9.3, CAL= 329.5,   9.3, ROT= 240.5,  -9.3

2021-11-17T18:09:53.226Z,1637172593.226 [DAT](INFO): DAT read: 

2021-11-17T18:09:53.226Z,1637172593.226 [DAT](INFO): DAT read: DATA(0002):~~

2021-11-17T18:09:53.227Z,1637172593.227 [DAT](INFO): Got DATA 2
2021-11-17T18:09:53.232Z,1637172593.232 [DAT](INFO): DAT read: Source:001  Destination:007

2021-11-17T18:09:53.232Z,1637172593.232 [DAT](INFO): Got Src/Dest after DATA 
2021-11-17T18:09:53.232Z,1637172593.232 [DAT](INFO): DATA Src=1, Dst=7
2021-11-17T18:09:53.234Z,1637172593.234 [DAT](INFO): DAT read: CRC:Pass MPD:03.7 PSNR:12.4 AGC:88 SPD:+0.0 CCERR:010

2021-11-17T18:09:53.234Z,1637172593.234 [DAT](INFO): Got CRC:Pass
2021-11-17T18:09:53.234Z,1637172593.234 [DAT](INFO): Got CRC:Pass
2021-11-17T18:09:53.234Z,1637172593.234 [DAT](INFO): Incoming data is intended for us
2021-11-17T18:09:53.234Z,1637172593.234 [DAT](DEBUG): In parseResponses, got ack so set commsState_ = SENDING_VERIFIED
2021-11-17T18:09:53.234Z,1637172593.234 [DAT](INFO): Got ack
2021-11-17T18:09:53.234Z,1637172593.234 [DAT](INFO): DAT read: 

2021-11-17T18:09:53.235Z,1637172593.235 [DAT](INFO): DAT read: <EOP>

2021-11-17T18:09:53.240Z,1637172593.240 [DAT](INFO): Sent 184 bytes from file Logs/20211117T180653/Courier0000.lzma.parts
2021-11-17T18:09:53.240Z,1637172593.240 [DAT](INFO): Packets left to send: 1
2021-11-17T18:09:53.242Z,1637172593.242 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-17T18:09:53.243Z,1637172593.243 [DAT](INFO): #Rx 2: Read direction message, but no range.
2021-11-17T18:09:53.248Z,1637172593.248 [DAT](INFO): direction in vehicle frame: [ -0.485951 forward, -0.858916 starboard, -0.161604 keelward ]
2021-11-17T18:09:54.182Z,1637172594.182 [Startup:StartupSatComms:B] Stopped
2021-11-17T18:09:54.182Z,1637172594.182 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2021-11-17T18:09:54.182Z,1637172594.182 [Startup:StartupSatComms] Stopped
2021-11-17T18:09:54.182Z,1637172594.182 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2021-11-17T18:09:54.183Z,1637172594.183 [Startup](INFO): Completed Startup
2021-11-17T18:09:54.183Z,1637172594.183 [MissionManager](INFO): Startup is completed.
2021-11-17T18:09:54.184Z,1637172594.184 [MissionManager](INFO): Uninitializing Mission Startup
2021-11-17T18:09:54.184Z,1637172594.184 [Startup] Stopped
2021-11-17T18:09:54.184Z,1637172594.184 [Startup](DEBUG): Aggregate::uninitialize Startup
2021-11-17T18:09:54.184Z,1637172594.184 [Startup:A.GoToSurface] Stopped
2021-11-17T18:09:54.184Z,1637172594.184 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2021-11-17T18:09:54.281Z,1637172594.281 [MissionManager](IMPORTANT): Started mission Default
2021-11-17T18:09:54.281Z,1637172594.281 [Default] Running Loop=1
2021-11-17T18:09:54.282Z,1637172594.282 [Default](DEBUG): Aggregate::initialize Default
2021-11-17T18:09:54.282Z,1637172594.282 [Default:B.GoToSurface] Running Loop=1
2021-11-17T18:09:54.282Z,1637172594.282 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2021-11-17T18:09:54.282Z,1637172594.282 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2021-11-17T18:09:54.282Z,1637172594.282 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2021-11-17T18:09:54.283Z,1637172594.283 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2021-11-17T18:09:54.283Z,1637172594.283 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2021-11-17T18:09:54.288Z,1637172594.288 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2021-11-17T18:09:54.288Z,1637172594.288 [Default:A.Wait] Running Loop=1
2021-11-17T18:09:54.288Z,1637172594.288 [Default:A.Wait](DEBUG): Initialize Wait Component.
2021-11-17T18:10:03.524Z,1637172603.524 [DataOverHttps](INFO): Sending 398 bytes from file Logs/20211117T174345/Express0010.lzma
2021-11-17T18:10:04.525Z,1637172604.525 [DataOverHttps](INFO): Moved sent file to Logs/20211117T174345/Express0010.lzma.bak
2021-11-17T18:10:04.525Z,1637172604.525 [DataOverHttps](INFO): SBD MOMSN=16261889
2021-11-17T18:10:07.577Z,1637172607.577 [Default:A.Wait](INFO): Done Waiting.
2021-11-17T18:10:07.577Z,1637172607.577 [Default:A.Wait] Stopped
2021-11-17T18:10:07.577Z,1637172607.577 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2021-11-17T18:10:07.994Z,1637172607.994 [Default:CheckIn] Running Loop=1
2021-11-17T18:10:07.994Z,1637172607.994 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-11-17T18:10:07.995Z,1637172607.995 [Default:CheckIn:Read_GPS] Running Loop=1
2021-11-17T18:10:08.484Z,1637172608.484 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2021-11-17T18:11:08.171Z,1637172668.171 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-11-17T18:10:07.0Z
2021-11-17T18:11:08.171Z,1637172668.171 [Default:CheckIn:Read_GPS] Stopped
2021-11-17T18:11:08.171Z,1637172668.171 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-11-17T18:11:08.565Z,1637172668.565 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2021-11-17T18:11:09.741Z,1637172669.741 [DAT](INFO): #Outgoing data=1
2021-11-17T18:11:09.741Z,1637172669.741 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-17T18:11:09.829Z,1637172669.829 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-17T18:11:13.042Z,1637172673.042 [DAT](INFO): DAT read: Forwarding Delay UpTx time:18:10:35.0213

2021-11-17T18:11:13.042Z,1637172673.042 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-17T18:11:15.403Z,1637172675.403 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20211117T180653/Courier0004.lzma
2021-11-17T18:11:16.405Z,1637172676.405 [DataOverHttps](INFO): Moved sent file to Logs/20211117T180653/Courier0004.lzma.bak
2021-11-17T18:11:16.405Z,1637172676.405 [DataOverHttps](INFO): SBD MOMSN=16261897
2021-11-17T18:11:20.342Z,1637172680.342 [DAT](INFO): DAT read: Rx Time:18:10:41.7973

2021-11-17T18:11:20.342Z,1637172680.342 [DAT](INFO): received an acoustic signal
2021-11-17T18:11:21.542Z,1637172681.542 [DAT](INFO): DAT read: 18:10:41.7973 LVL= 32752, 32753, 32754, 32755, AGC= 87, IDX= 478, 0.11,-2.695,-2.638,-2.695,-2.683, PHS=-0.016, 0.089,-0.027, RAW= 334.8,  -8.2, CAL= 335.9, -10.6, ROT= 234.1,  10.6

2021-11-17T18:11:21.543Z,1637172681.543 [DAT](INFO): got valid direction response:
 18:10:41.7973 LVL= 32752, 32753, 32754, 32755, AGC= 87, IDX= 478, 0.11,-2.695,-2.638,-2.695,-2.683, PHS=-0.016, 0.089,-0.027, RAW= 334.8,  -8.2, CAL= 335.9, -10.6, ROT= 234.1,  10.6

2021-11-17T18:11:21.543Z,1637172681.543 [DAT](INFO): DAT read: 

2021-11-17T18:11:21.544Z,1637172681.544 [DAT](INFO): DAT read: DATA(0002):~~

2021-11-17T18:11:21.544Z,1637172681.544 [DAT](INFO): Got DATA 2
2021-11-17T18:11:21.545Z,1637172681.545 [DAT](INFO): DAT read: Source:001  Destination:007

2021-11-17T18:11:21.545Z,1637172681.545 [DAT](INFO): Got Src/Dest after DATA 
2021-11-17T18:11:21.546Z,1637172681.546 [DAT](INFO): DATA Src=1, Dst=7
2021-11-17T18:11:21.547Z,1637172681.547 [DAT](INFO): DAT read: CRC:Pass MPD:03.9 PSNR:12.6 AGC:91 SPD:+0.0 CCERR:010

2021-11-17T18:11:21.551Z,1637172681.551 [DAT](INFO): Got CRC:Pass
2021-11-17T18:11:21.552Z,1637172681.552 [DAT](INFO): Got CRC:Pass
2021-11-17T18:11:21.552Z,1637172681.552 [DAT](INFO): Incoming data is intended for us
2021-11-17T18:11:21.552Z,1637172681.552 [DAT](DEBUG): In parseResponses, got ack so set commsState_ = SENDING_VERIFIED
2021-11-17T18:11:21.552Z,1637172681.552 [DAT](INFO): Got ack
2021-11-17T18:11:21.552Z,1637172681.552 [DAT](INFO): DAT read: 

2021-11-17T18:11:21.553Z,1637172681.553 [DAT](INFO): DAT read: <EOP>

2021-11-17T18:11:21.553Z,1637172681.553 [DAT](INFO): Sent 39 bytes from file Logs/20211117T180653/Courier0004.lzma.parts
2021-11-17T18:11:21.554Z,1637172681.554 [DAT](INFO): Packets left to send: 0
2021-11-17T18:11:21.561Z,1637172681.561 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-17T18:11:21.561Z,1637172681.561 [DAT](INFO): #Rx 3: Read direction message, but no range.
2021-11-17T18:11:21.562Z,1637172681.562 [DAT](INFO): direction in vehicle frame: [ -0.576366 forward, -0.796219 starboard, 0.183951 keelward ]
2021-11-17T18:11:22.924Z,1637172682.924 [Default:CheckIn:Read_Iridium] Stopped
2021-11-17T18:11:22.925Z,1637172682.925 [Default:CheckIn:C.Wait] Running Loop=1
2021-11-17T18:11:22.925Z,1637172682.925 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-11-17T18:11:34.751Z,1637172694.751 [DataOverHttps](INFO): Sending 413 bytes from file Logs/20211117T175124/Express0001.lzma
2021-11-17T18:11:35.754Z,1637172695.754 [DataOverHttps](INFO): Moved sent file to Logs/20211117T175124/Express0001.lzma.bak
2021-11-17T18:11:35.754Z,1637172695.754 [DataOverHttps](INFO): SBD MOMSN=16261900
2021-11-17T18:12:23.209Z,1637172743.209 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-11-17T18:12:23.209Z,1637172743.209 [Default:CheckIn:C.Wait] Stopped
2021-11-17T18:12:23.209Z,1637172743.209 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-11-17T18:12:23.209Z,1637172743.209 [Default:CheckIn:D] Running Loop=1
2021-11-17T18:12:23.629Z,1637172743.629 [Default:CheckIn:D] Stopped
2021-11-17T18:12:23.629Z,1637172743.629 [Default:CheckIn:E] Running Loop=1
2021-11-17T18:12:24.018Z,1637172744.018 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 2.489120 min 
2021-11-17T18:12:24.018Z,1637172744.018 [Default:CheckIn:E] Stopped
2021-11-17T18:12:24.018Z,1637172744.018 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-11-17T18:12:24.018Z,1637172744.018 [Default:CheckIn] Stopped
2021-11-17T18:12:24.018Z,1637172744.018 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-11-17T18:12:24.019Z,1637172744.019 [Default:CheckIn](INFO): Running loop #2
2021-11-17T18:12:24.019Z,1637172744.019 [Default:CheckIn] Running Loop=2
2021-11-17T18:12:24.019Z,1637172744.019 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-11-17T18:12:24.019Z,1637172744.019 [Default:CheckIn:Read_GPS] Running Loop=1
2021-11-17T18:12:48.216Z,1637172768.216 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2021-11-17T18:13:24.206Z,1637172804.206 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-11-17T18:12:24.0Z
2021-11-17T18:13:24.206Z,1637172804.206 [Default:CheckIn:Read_GPS] Stopped
2021-11-17T18:13:24.206Z,1637172804.206 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-11-17T18:13:25.770Z,1637172805.770 [DAT](INFO): #Outgoing data=1
2021-11-17T18:13:25.771Z,1637172805.771 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-17T18:13:25.883Z,1637172805.883 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-17T18:13:29.478Z,1637172809.478 [DAT](INFO): DAT read: Forwarding Delay UpTx time:18:12:51.1190

2021-11-17T18:13:29.478Z,1637172809.478 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-17T18:13:31.195Z,1637172811.195 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20211117T180653/Courier0007.lzma
2021-11-17T18:13:32.197Z,1637172812.197 [DataOverHttps](INFO): Moved sent file to Logs/20211117T180653/Courier0007.lzma.bak
2021-11-17T18:13:32.197Z,1637172812.197 [DataOverHttps](INFO): SBD MOMSN=16261908
2021-11-17T18:13:36.750Z,1637172816.750 [DAT](INFO): DAT read: Rx Time:18:12:57.9000

2021-11-17T18:13:36.750Z,1637172816.750 [DAT](INFO): received an acoustic signal
2021-11-17T18:13:37.574Z,1637172817.574 [DAT](INFO): DAT read: 18:12:57.9000 LVL= 32752, 32753, 32754, 32755, AGC= 86, IDX= 498,-0.20, 2.359, 2.436, 2.372, 2.400, PHS=-0.046, 0.080,-0.044, RAW= 329.1,   1.6, CAL= 329.4,  -0.7, ROT= 240.6,   0.7

2021-11-17T18:13:37.575Z,1637172817.575 [DAT](INFO): got valid direction response:
 18:12:57.9000 LVL= 32752, 32753, 32754, 32755, AGC= 86, IDX= 498,-0.20, 2.359, 2.436, 2.372, 2.400, PHS=-0.046, 0.080,-0.044, RAW= 329.1,   1.6, CAL= 329.4,  -0.7, ROT= 240.6,   0.7

2021-11-17T18:13:37.576Z,1637172817.576 [DAT](INFO): DAT read: 

2021-11-17T18:13:37.576Z,1637172817.576 [DAT](INFO): DAT read: DATA(0002):~~

2021-11-17T18:13:37.577Z,1637172817.577 [DAT](INFO): Got DATA 2
2021-11-17T18:13:37.578Z,1637172817.578 [DAT](INFO): DAT read: Source:001  Destination:007

2021-11-17T18:13:37.578Z,1637172817.578 [DAT](INFO): Got Src/Dest after DATA 
2021-11-17T18:13:37.578Z,1637172817.578 [DAT](INFO): DATA Src=1, Dst=7
2021-11-17T18:13:37.580Z,1637172817.580 [DAT](INFO): DAT read: CRC:Pass MPD:03.8 PSNR:12.2 AGC:90 SPD:-0.1 CCERR:010

2021-11-17T18:13:37.580Z,1637172817.580 [DAT](INFO): Got CRC:Pass
2021-11-17T18:13:37.580Z,1637172817.580 [DAT](INFO): Got CRC:Pass
2021-11-17T18:13:37.580Z,1637172817.580 [DAT](INFO): Incoming data is intended for us
2021-11-17T18:13:37.580Z,1637172817.580 [DAT](DEBUG): In parseResponses, got ack so set commsState_ = SENDING_VERIFIED
2021-11-17T18:13:37.580Z,1637172817.580 [DAT](INFO): Got ack
2021-11-17T18:13:37.581Z,1637172817.581 [DAT](INFO): DAT read: 

2021-11-17T18:13:37.582Z,1637172817.582 [DAT](INFO): Sent 39 bytes from file Logs/20211117T180653/Courier0007.lzma.parts
2021-11-17T18:13:37.582Z,1637172817.582 [DAT](INFO): Packets left to send: 0
2021-11-17T18:13:37.596Z,1637172817.596 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-17T18:13:37.597Z,1637172817.597 [DAT](INFO): #Rx 4: Read direction message, but no range.
2021-11-17T18:13:37.598Z,1637172817.598 [DAT](INFO): direction in vehicle frame: [ -0.490867 forward, -0.871149 starboard, 0.012217 keelward ]
2021-11-17T18:13:37.957Z,1637172817.957 [DAT](INFO): DAT read: <EOP>

2021-11-17T18:13:38.947Z,1637172818.947 [Default:CheckIn:Read_Iridium] Stopped
2021-11-17T18:13:38.947Z,1637172818.947 [Default:CheckIn:C.Wait] Running Loop=1
2021-11-17T18:13:38.952Z,1637172818.952 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-11-17T18:13:49.027Z,1637172829.027 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20211117T175124/Express0004.lzma
2021-11-17T18:13:50.029Z,1637172830.029 [DataOverHttps](INFO): Moved sent file to Logs/20211117T175124/Express0004.lzma.bak
2021-11-17T18:13:50.029Z,1637172830.029 [DataOverHttps](INFO): SBD MOMSN=16261910
2021-11-17T18:13:57.177Z,1637172837.177 [NAL9602](INFO): Not Powering down - fast GPS
2021-11-17T18:14:32.322Z,1637172872.322 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2021-11-17T18:14:32.346Z,1637172872.346 [BPC1](INFO): Received data from all battery sticks.
2021-11-17T18:14:39.200Z,1637172879.200 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-11-17T18:14:39.200Z,1637172879.200 [Default:CheckIn:C.Wait] Stopped
2021-11-17T18:14:39.200Z,1637172879.200 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-11-17T18:14:39.201Z,1637172879.201 [Default:CheckIn:D] Running Loop=1
2021-11-17T18:14:39.613Z,1637172879.613 [Default:CheckIn:D] Stopped
2021-11-17T18:14:39.613Z,1637172879.613 [Default:CheckIn:E] Running Loop=1
2021-11-17T18:14:40.016Z,1637172880.016 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 4.755528 min 
2021-11-17T18:14:40.016Z,1637172880.016 [Default:CheckIn:E] Stopped
2021-11-17T18:14:40.017Z,1637172880.017 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-11-17T18:14:40.017Z,1637172880.017 [Default:CheckIn] Stopped
2021-11-17T18:14:40.017Z,1637172880.017 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-11-17T18:14:40.017Z,1637172880.017 [Default:CheckIn](INFO): Running loop #3
2021-11-17T18:14:40.017Z,1637172880.017 [Default:CheckIn] Running Loop=3
2021-11-17T18:14:40.017Z,1637172880.017 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-11-17T18:14:40.017Z,1637172880.017 [Default:CheckIn:Read_GPS] Running Loop=1
2021-11-17T18:15:12.721Z,1637172912.721 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2021-11-17T18:15:12.796Z,1637172912.796 [NAL9602](ERROR): received: 
+CSQ:0

OK
2021-11-17T18:15:40.218Z,1637172940.218 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-11-17T18:14:40.0Z
2021-11-17T18:15:40.219Z,1637172940.219 [Default:CheckIn:Read_GPS] Stopped
2021-11-17T18:15:40.219Z,1637172940.219 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-11-17T18:15:42.455Z,1637172942.455 [DAT](INFO): #Outgoing data=1
2021-11-17T18:15:42.455Z,1637172942.455 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-17T18:15:42.535Z,1637172942.535 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-17T18:15:46.158Z,1637172946.158 [DAT](INFO): DAT read: Forwarding Delay UpTx time:18:15:07.8666

2021-11-17T18:15:46.159Z,1637172946.159 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-17T18:15:48.683Z,1637172948.683 [DataOverHttps](INFO): Sending 168 bytes from file Logs/20211117T180653/Courier0010.lzma
2021-11-17T18:15:49.685Z,1637172949.685 [DataOverHttps](INFO): Moved sent file to Logs/20211117T180653/Courier0010.lzma.bak
2021-11-17T18:15:49.685Z,1637172949.685 [DataOverHttps](INFO): SBD MOMSN=16261922
2021-11-17T18:15:54.653Z,1637172954.653 [DAT](INFO): DAT read: Rx Time:18:15:16.1028

2021-11-17T18:15:54.653Z,1637172954.653 [DAT](INFO): received an acoustic signal
2021-11-17T18:15:55.870Z,1637172955.870 [DAT](INFO): DAT read: 18:15:16.1028 LVL= 32752, 32753, 32754, 32755, AGC= 86, IDX= 229, 0.22,-1.950,-1.866,-1.938,-1.887, PHS=-0.067, 0.066,-0.066, RAW= 329.8,  10.2, CAL= 330.0,  10.5, ROT= 240.0, -10.5

2021-11-17T18:15:55.876Z,1637172955.876 [DAT](INFO): got valid direction response:
 18:15:16.1028 LVL= 32752, 32753, 32754, 32755, AGC= 86, IDX= 229, 0.22,-1.950,-1.866,-1.938,-1.887, PHS=-0.067, 0.066,-0.066, RAW= 329.8,  10.2, CAL= 330.0,  10.5, ROT= 240.0, -10.5

2021-11-17T18:15:55.877Z,1637172955.877 [DAT](INFO): DAT read: 

2021-11-17T18:15:55.877Z,1637172955.877 [DAT](INFO): DAT read: DATA(0002):~~

2021-11-17T18:15:55.878Z,1637172955.878 [DAT](INFO): Got DATA 2
2021-11-17T18:15:55.878Z,1637172955.878 [DAT](INFO): DAT read: Source:001  Destination:007

2021-11-17T18:15:55.879Z,1637172955.879 [DAT](INFO): Got Src/Dest after DATA 
2021-11-17T18:15:55.879Z,1637172955.879 [DAT](INFO): DATA Src=1, Dst=7
2021-11-17T18:15:55.913Z,1637172955.913 [DAT](INFO): DAT read: CRC:Pass MPD:03.7 PSNR:12.2 AGC:89 SPD:+0.0 CCERR:010

2021-11-17T18:15:55.913Z,1637172955.913 [DAT](INFO): Got CRC:Pass
2021-11-17T18:15:55.913Z,1637172955.913 [DAT](INFO): Got CRC:Pass
2021-11-17T18:15:55.913Z,1637172955.913 [DAT](INFO): Incoming data is intended for us
2021-11-17T18:15:55.914Z,1637172955.914 [DAT](DEBUG): In parseResponses, got ack so set commsState_ = SENDING_VERIFIED
2021-11-17T18:15:55.914Z,1637172955.914 [DAT](INFO): Got ack
2021-11-17T18:15:55.914Z,1637172955.914 [DAT](INFO): DAT read: 

2021-11-17T18:15:55.914Z,1637172955.914 [DAT](INFO): DAT read: <EOP>

2021-11-17T18:15:55.919Z,1637172955.919 [DAT](INFO): Sent 168 bytes from file Logs/20211117T180653/Courier0010.lzma.parts
2021-11-17T18:15:55.920Z,1637172955.920 [DAT](INFO): Packets left to send: 0
2021-11-17T18:15:55.922Z,1637172955.922 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-17T18:15:55.922Z,1637172955.922 [DAT](INFO): #Rx 5: Read direction message, but no range.
2021-11-17T18:15:55.931Z,1637172955.931 [DAT](INFO): direction in vehicle frame: [ -0.491627 forward, -0.851524 starboard, -0.182236 keelward ]
2021-11-17T18:15:56.866Z,1637172956.866 [Default:CheckIn:Read_Iridium] Stopped
2021-11-17T18:15:56.866Z,1637172956.866 [Default:CheckIn:C.Wait] Running Loop=1
2021-11-17T18:15:56.866Z,1637172956.866 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-11-17T18:16:06.061Z,1637172966.061 [DataOverHttps](INFO): Sending 1170 bytes from file Logs/20211117T175209/Express0001.lzma
2021-11-17T18:16:07.062Z,1637172967.062 [DataOverHttps](INFO): Moved sent file to Logs/20211117T175209/Express0001.lzma.bak
2021-11-17T18:16:07.062Z,1637172967.062 [DataOverHttps](INFO): SBD MOMSN=16261924
2021-11-17T18:16:57.129Z,1637173017.129 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-11-17T18:16:57.129Z,1637173017.129 [Default:CheckIn:C.Wait] Stopped
2021-11-17T18:16:57.129Z,1637173017.129 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-11-17T18:16:57.129Z,1637173017.129 [Default:CheckIn:D] Running Loop=1
2021-11-17T18:16:57.548Z,1637173017.548 [Default:CheckIn:D] Stopped
2021-11-17T18:16:57.548Z,1637173017.548 [Default:CheckIn:E] Running Loop=1
2021-11-17T18:16:57.958Z,1637173017.958 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 7.054435 min 
2021-11-17T18:16:57.958Z,1637173017.958 [Default:CheckIn:E] Stopped
2021-11-17T18:16:57.958Z,1637173017.958 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-11-17T18:16:57.958Z,1637173017.958 [Default:CheckIn] Stopped
2021-11-17T18:16:57.958Z,1637173017.958 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-11-17T18:16:57.959Z,1637173017.959 [Default:CheckIn](INFO): Running loop #4
2021-11-17T18:16:57.959Z,1637173017.959 [Default:CheckIn] Running Loop=4
2021-11-17T18:16:57.959Z,1637173017.959 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-11-17T18:16:57.959Z,1637173017.959 [Default:CheckIn:Read_GPS] Running Loop=1
2021-11-17T18:17:58.132Z,1637173078.132 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-11-17T18:16:57.0Z
2021-11-17T18:17:58.132Z,1637173078.132 [Default:CheckIn:Read_GPS] Stopped
2021-11-17T18:17:58.132Z,1637173078.132 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-11-17T18:17:59.824Z,1637173079.824 [DAT](INFO): #Outgoing data=1
2021-11-17T18:17:59.825Z,1637173079.825 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-17T18:17:59.910Z,1637173079.910 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-17T18:18:03.115Z,1637173083.115 [DAT](INFO): DAT read: Forwarding Delay UpTx time:18:17:25.1143

2021-11-17T18:18:03.115Z,1637173083.115 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-17T18:18:05.435Z,1637173085.435 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20211117T180653/Courier0013.lzma
2021-11-17T18:18:06.437Z,1637173086.437 [DataOverHttps](INFO): Moved sent file to Logs/20211117T180653/Courier0013.lzma.bak
2021-11-17T18:18:06.438Z,1637173086.438 [DataOverHttps](INFO): SBD MOMSN=16261971
2021-11-17T18:18:10.797Z,1637173090.797 [DAT](INFO): DAT read: Rx Time:18:17:31.9553

2021-11-17T18:18:10.797Z,1637173090.797 [DAT](INFO): received an acoustic signal
2021-11-17T18:18:11.621Z,1637173091.621 [DAT](INFO): DAT read: 18:17:31.9553 LVL= 32752, 32753, 32754, 32755, AGC= 87, IDX= 488,-0.09, 1.983, 2.042, 1.987, 1.998, PHS=-0.019, 0.088,-0.026, RAW= 333.4,  -7.9, CAL= 334.5, -10.3, ROT= 235.5,  10.3

2021-11-17T18:18:11.623Z,1637173091.623 [DAT](INFO): got valid direction response:
 18:17:31.9553 LVL= 32752, 32753, 32754, 32755, AGC= 87, IDX= 488,-0.09, 1.983, 2.042, 1.987, 1.998, PHS=-0.019, 0.088,-0.026, RAW= 333.4,  -7.9, CAL= 334.5, -10.3, ROT= 235.5,  10.3

2021-11-17T18:18:11.639Z,1637173091.639 [DAT](INFO): DAT read: 

2021-11-17T18:18:11.640Z,1637173091.640 [DAT](INFO): DAT read: DATA(0002):~~

2021-11-17T18:18:11.640Z,1637173091.640 [DAT](INFO): Got DATA 2
2021-11-17T18:18:11.641Z,1637173091.641 [DAT](INFO): DAT read: Source:001  Destination:007

2021-11-17T18:18:11.641Z,1637173091.641 [DAT](INFO): Got Src/Dest after DATA 
2021-11-17T18:18:11.642Z,1637173091.642 [DAT](INFO): DATA Src=1, Dst=7
2021-11-17T18:18:11.643Z,1637173091.643 [DAT](INFO): DAT read: CRC:Pass MPD:03.7 PSNR:12.1 AGC:86 SPD:+0.0 CCERR:010

2021-11-17T18:18:11.643Z,1637173091.643 [DAT](INFO): Got CRC:Pass
2021-11-17T18:18:11.643Z,1637173091.643 [DAT](INFO): Got CRC:Pass
2021-11-17T18:18:11.644Z,1637173091.644 [DAT](INFO): Incoming data is intended for us
2021-11-17T18:18:11.644Z,1637173091.644 [DAT](DEBUG): In parseResponses, got ack so set commsState_ = SENDING_VERIFIED
2021-11-17T18:18:11.644Z,1637173091.644 [DAT](INFO): Got ack
2021-11-17T18:18:11.644Z,1637173091.644 [DAT](INFO): DAT read: 

2021-11-17T18:18:11.645Z,1637173091.645 [DAT](INFO): DAT read: <EOP>

2021-11-17T18:18:11.645Z,1637173091.645 [DAT](INFO): Sent 39 bytes from file Logs/20211117T180653/Courier0013.lzma.parts
2021-11-17T18:18:11.645Z,1637173091.645 [DAT](INFO): Packets left to send: 0
2021-11-17T18:18:11.688Z,1637173091.688 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-17T18:18:11.723Z,1637173091.723 [DAT](INFO): #Rx 6: Read direction message, but no range.
2021-11-17T18:18:11.724Z,1637173091.724 [DAT](INFO): direction in vehicle frame: [ -0.557279 forward, -0.810845 starboard, 0.178802 keelward ]
2021-11-17T18:18:12.978Z,1637173092.978 [Default:CheckIn:Read_Iridium] Stopped
2021-11-17T18:18:12.978Z,1637173092.978 [Default:CheckIn:C.Wait] Running Loop=1
2021-11-17T18:18:12.979Z,1637173092.979 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-11-17T18:18:23.199Z,1637173103.199 [DataOverHttps](INFO): Sending 105 bytes from file Logs/20211117T175209/Express0005.lzma
2021-11-17T18:18:24.201Z,1637173104.201 [DataOverHttps](INFO): Moved sent file to Logs/20211117T175209/Express0005.lzma.bak
2021-11-17T18:18:24.202Z,1637173104.202 [DataOverHttps](INFO): SBD MOMSN=16261973
2021-11-17T18:19:13.261Z,1637173153.261 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-11-17T18:19:13.261Z,1637173153.261 [Default:CheckIn:C.Wait] Stopped
2021-11-17T18:19:13.262Z,1637173153.261 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-11-17T18:19:13.262Z,1637173153.262 [Default:CheckIn:D] Running Loop=1
2021-11-17T18:19:13.686Z,1637173153.686 [Default:CheckIn:D] Stopped
2021-11-17T18:19:13.686Z,1637173153.686 [Default:CheckIn:E] Running Loop=1
2021-11-17T18:19:14.080Z,1637173154.080 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 9.323402 min 
2021-11-17T18:19:14.080Z,1637173154.080 [Default:CheckIn:E] Stopped
2021-11-17T18:19:14.080Z,1637173154.080 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-11-17T18:19:14.080Z,1637173154.080 [Default:CheckIn] Stopped
2021-11-17T18:19:14.080Z,1637173154.080 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-11-17T18:19:14.081Z,1637173154.081 [Default:CheckIn](INFO): Running loop #5
2021-11-17T18:19:14.081Z,1637173154.081 [Default:CheckIn] Running Loop=5
2021-11-17T18:19:14.081Z,1637173154.081 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-11-17T18:19:14.081Z,1637173154.081 [Default:CheckIn:Read_GPS] Running Loop=1
2021-11-17T18:19:44.354Z,1637173184.354 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2021-11-17T18:19:45.161Z,1637173185.161 [NAL9602](FAULT): GPS failed to acquire within timeout.
2021-11-17T18:19:45.161Z,1637173185.161 [NAL9602] Data Fault, FailCount= 1
2021-11-17T18:19:45.161Z,1637173185.161 [NAL9602](ERROR): Data Fault
2021-11-17T18:19:45.204Z,1637173185.204 [CBIT](ERROR): Data Fault in component: NAL9602
2021-11-17T18:19:45.569Z,1637173185.569 [NAL9602](INFO): Powering down
2021-11-17T18:19:46.407Z,1637173186.407 [CBIT](INFO): Clearing failed state for component NAL9602
2021-11-17T18:19:46.407Z,1637173186.407 [NAL9602] No Fault, FailCount= 1
2021-11-17T18:20:14.306Z,1637173214.306 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-11-17T18:19:14.1Z
2021-11-17T18:20:14.306Z,1637173214.306 [Default:CheckIn:Read_GPS] Stopped
2021-11-17T18:20:14.306Z,1637173214.306 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-11-17T18:20:16.768Z,1637173216.768 [DAT](INFO): #Outgoing data=1
2021-11-17T18:20:16.768Z,1637173216.768 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-17T18:20:16.888Z,1637173216.888 [NAL9602](INFO): Powering up NAL9602
2021-11-17T18:20:16.890Z,1637173216.890 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-17T18:20:20.482Z,1637173220.482 [DAT](INFO): DAT read: Forwarding Delay UpTx time:18:19:42.1120

2021-11-17T18:20:20.482Z,1637173220.482 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-17T18:20:25.503Z,1637173225.503 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20211117T180653/Courier0016.lzma
2021-11-17T18:20:26.505Z,1637173226.505 [DataOverHttps](INFO): Moved sent file to Logs/20211117T180653/Courier0016.lzma.bak
2021-11-17T18:20:26.505Z,1637173226.505 [DataOverHttps](INFO): SBD MOMSN=16261976
2021-11-17T18:20:27.761Z,1637173227.761 [NAL9602](INFO): NAL9602 initialized
2021-11-17T18:20:27.762Z,1637173227.762 [DAT](INFO): DAT read: Rx Time:18:19:48.9080

2021-11-17T18:20:27.762Z,1637173227.762 [DAT](INFO): received an acoustic signal
2021-11-17T18:20:28.572Z,1637173228.572 [DAT](INFO): DAT read: 18:19:48.9080 LVL= 32752, 32753, 32754, 32755, AGC= 85, IDX= 490, 0.17,-1.848,-1.762,-1.833,-1.785, PHS=-0.067, 0.066,-0.063, RAW= 328.4,   9.8, CAL= 328.5,  10.0, ROT= 241.5, -10.0

2021-11-17T18:20:28.574Z,1637173228.574 [DAT](INFO): got valid direction response:
 18:19:48.9080 LVL= 32752, 32753, 32754, 32755, AGC= 85, IDX= 490, 0.17,-1.848,-1.762,-1.833,-1.785, PHS=-0.067, 0.066,-0.063, RAW= 328.4,   9.8, CAL= 328.5,  10.0, ROT= 241.5, -10.0

2021-11-17T18:20:28.574Z,1637173228.574 [DAT](INFO): DAT read: 

2021-11-17T18:20:28.575Z,1637173228.575 [DAT](INFO): DAT read: DATA(0002):~~

2021-11-17T18:20:28.600Z,1637173228.600 [DAT](INFO): Got DATA 2
2021-11-17T18:20:28.601Z,1637173228.601 [DAT](INFO): DAT read: Source:001  Destination:007

2021-11-17T18:20:28.601Z,1637173228.601 [DAT](INFO): Got Src/Dest after DATA 
2021-11-17T18:20:28.601Z,1637173228.601 [DAT](INFO): DATA Src=1, Dst=7
2021-11-17T18:20:28.603Z,1637173228.603 [DAT](INFO): DAT read: CRC:Pass MPD:03.7 PSNR:11.6 AGC:89 SPD:+0.1 CCERR:009

2021-11-17T18:20:28.603Z,1637173228.603 [DAT](INFO): Got CRC:Pass
2021-11-17T18:20:28.603Z,1637173228.603 [DAT](INFO): Got CRC:Pass
2021-11-17T18:20:28.603Z,1637173228.603 [DAT](INFO): Incoming data is intended for us
2021-11-17T18:20:28.616Z,1637173228.616 [DAT](DEBUG): In parseResponses, got ack so set commsState_ = SENDING_VERIFIED
2021-11-17T18:20:28.616Z,1637173228.616 [DAT](INFO): Got ack
2021-11-17T18:20:28.617Z,1637173228.617 [DAT](INFO): DAT read: 

2021-11-17T18:20:28.617Z,1637173228.617 [DAT](INFO): DAT read: <EOP>

2021-11-17T18:20:28.618Z,1637173228.618 [DAT](INFO): Sent 39 bytes from file Logs/20211117T180653/Courier0016.lzma.parts
2021-11-17T18:20:28.618Z,1637173228.618 [DAT](INFO): Packets left to send: 0
2021-11-17T18:20:28.620Z,1637173228.620 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-17T18:20:28.621Z,1637173228.621 [DAT](INFO): #Rx 7: Read direction message, but no range.
2021-11-17T18:20:28.622Z,1637173228.622 [DAT](INFO): direction in vehicle frame: [ -0.469910 forward, -0.865466 starboard, -0.173648 keelward ]
2021-11-17T18:20:29.451Z,1637173229.451 [Default:CheckIn:Read_Iridium] Stopped
2021-11-17T18:20:29.452Z,1637173229.452 [Default:CheckIn:C.Wait] Running Loop=1
2021-11-17T18:20:29.452Z,1637173229.452 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-11-17T18:20:42.512Z,1637173242.512 [DataOverHttps](INFO): Sending 446 bytes from file Logs/20211117T175209/Express0008.lzma
2021-11-17T18:20:43.513Z,1637173243.513 [DataOverHttps](INFO): Moved sent file to Logs/20211117T175209/Express0008.lzma.bak
2021-11-17T18:20:43.513Z,1637173243.513 [DataOverHttps](INFO): SBD MOMSN=16261979
2021-11-17T18:20:58.573Z,1637173258.573 [NAL9602](INFO): Not Powering down - fast GPS
2021-11-17T18:21:29.688Z,1637173289.688 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-11-17T18:21:29.689Z,1637173289.689 [Default:CheckIn:C.Wait] Stopped
2021-11-17T18:21:29.689Z,1637173289.689 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-11-17T18:21:29.689Z,1637173289.689 [Default:CheckIn:D] Running Loop=1
2021-11-17T18:21:30.093Z,1637173290.093 [Default:CheckIn:D] Stopped
2021-11-17T18:21:30.093Z,1637173290.093 [Default:CheckIn:E] Running Loop=1
2021-11-17T18:21:30.501Z,1637173290.501 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 11.596851 min 
2021-11-17T18:21:30.501Z,1637173290.501 [Default:CheckIn:E] Stopped
2021-11-17T18:21:30.501Z,1637173290.501 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-11-17T18:21:30.501Z,1637173290.501 [Default:CheckIn] Stopped
2021-11-17T18:21:30.501Z,1637173290.501 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-11-17T18:21:30.501Z,1637173290.501 [Default:CheckIn](INFO): Running loop #6
2021-11-17T18:21:30.501Z,1637173290.501 [Default:CheckIn] Running Loop=6
2021-11-17T18:21:30.502Z,1637173290.502 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-11-17T18:21:30.502Z,1637173290.502 [Default:CheckIn:Read_GPS] Running Loop=1
2021-11-17T18:22:06.108Z,1637173326.108 [CBIT](INFO): Clearing failed state for component DropWeight
2021-11-17T18:22:06.108Z,1637173326.108 [DropWeight] No Fault, FailCount= 1
2021-11-17T18:22:30.690Z,1637173350.690 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-11-17T18:21:30.5Z
2021-11-17T18:22:30.690Z,1637173350.690 [Default:CheckIn:Read_GPS] Stopped
2021-11-17T18:22:30.690Z,1637173350.690 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-11-17T18:22:32.246Z,1637173352.246 [DAT](INFO): #Outgoing data=1
2021-11-17T18:22:32.247Z,1637173352.247 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-17T18:22:32.349Z,1637173352.349 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-17T18:22:35.922Z,1637173355.922 [DAT](INFO): DAT read: Forwarding Delay UpTx time:18:21:57.5598

2021-11-17T18:22:35.923Z,1637173355.923 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-17T18:22:37.895Z,1637173357.895 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20211117T180653/Courier0019.lzma
2021-11-17T18:22:38.897Z,1637173358.897 [DataOverHttps](INFO): Moved sent file to Logs/20211117T180653/Courier0019.lzma.bak
2021-11-17T18:22:38.897Z,1637173358.897 [DataOverHttps](INFO): SBD MOMSN=16262003
2021-11-17T18:22:43.222Z,1637173363.222 [DAT](INFO): DAT read: Rx Time:18:22:04.3605

2021-11-17T18:22:43.222Z,1637173363.222 [DAT](INFO): received an acoustic signal
2021-11-17T18:22:44.029Z,1637173364.029 [DAT](INFO): DAT read: 18:22:04.3605 LVL= 32752, 32753, 32754, 32755, AGC= 84, IDX= 491,-0.01,-2.885,-2.784,-2.881,-2.807, PHS=-0.082, 0.067,-0.089, RAW= 332.2,  13.6, CAL= 332.5,  15.1, ROT= 237.5, -15.1

2021-11-17T18:22:44.030Z,1637173364.030 [DAT](INFO): got valid direction response:
 18:22:04.3605 LVL= 32752, 32753, 32754, 32755, AGC= 84, IDX= 491,-0.01,-2.885,-2.784,-2.881,-2.807, PHS=-0.082, 0.067,-0.089, RAW= 332.2,  13.6, CAL= 332.5,  15.1, ROT= 237.5, -15.1

2021-11-17T18:22:44.030Z,1637173364.030 [DAT](INFO): DAT read: 

2021-11-17T18:22:44.074Z,1637173364.074 [DAT](INFO): DAT read: DATA(0002):~~

2021-11-17T18:22:44.075Z,1637173364.075 [DAT](INFO): Got DATA 2
2021-11-17T18:22:44.076Z,1637173364.076 [DAT](INFO): DAT read: Source:001  Destination:007

2021-11-17T18:22:44.076Z,1637173364.076 [DAT](INFO): Got Src/Dest after DATA 
2021-11-17T18:22:44.076Z,1637173364.076 [DAT](INFO): DATA Src=1, Dst=7
2021-11-17T18:22:44.078Z,1637173364.078 [DAT](INFO): DAT read: CRC:Pass MPD:03.8 PSNR:11.5 AGC:89 SPD:+0.1 CCERR:010

2021-11-17T18:22:44.078Z,1637173364.078 [DAT](INFO): Got CRC:Pass
2021-11-17T18:22:44.078Z,1637173364.078 [DAT](INFO): Got CRC:Pass
2021-11-17T18:22:44.078Z,1637173364.078 [DAT](INFO): Incoming data is intended for us
2021-11-17T18:22:44.078Z,1637173364.078 [DAT](DEBUG): In parseResponses, got ack so set commsState_ = SENDING_VERIFIED
2021-11-17T18:22:44.078Z,1637173364.078 [DAT](INFO): Got ack
2021-11-17T18:22:44.078Z,1637173364.078 [DAT](INFO): DAT read: 

2021-11-17T18:22:44.079Z,1637173364.079 [DAT](INFO): DAT read: <EOP>

2021-11-17T18:22:44.080Z,1637173364.080 [DAT](INFO): Sent 39 bytes from file Logs/20211117T180653/Courier0019.lzma.parts
2021-11-17T18:22:44.080Z,1637173364.080 [DAT](INFO): Packets left to send: 0
2021-11-17T18:22:44.082Z,1637173364.082 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-17T18:22:44.082Z,1637173364.082 [DAT](INFO): #Rx 8: Read direction message, but no range.
2021-11-17T18:22:44.118Z,1637173364.118 [DAT](INFO): direction in vehicle frame: [ -0.518748 forward, -0.814271 starboard, -0.260505 keelward ]
2021-11-17T18:22:45.410Z,1637173365.410 [Default:CheckIn:Read_Iridium] Stopped
2021-11-17T18:22:45.410Z,1637173365.410 [Default:CheckIn:C.Wait] Running Loop=1
2021-11-17T18:22:45.410Z,1637173365.410 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-11-17T18:22:56.743Z,1637173376.743 [DataOverHttps](INFO): Sending 110 bytes from file Logs/20211117T175209/Express0011.lzma
2021-11-17T18:22:57.745Z,1637173377.745 [DataOverHttps](INFO): Moved sent file to Logs/20211117T175209/Express0011.lzma.bak
2021-11-17T18:22:57.745Z,1637173377.745 [DataOverHttps](INFO): SBD MOMSN=16262005
2021-11-17T18:23:45.718Z,1637173425.718 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-11-17T18:23:45.718Z,1637173425.718 [Default:CheckIn:C.Wait] Stopped
2021-11-17T18:23:45.718Z,1637173425.718 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-11-17T18:23:45.718Z,1637173425.718 [Default:CheckIn:D] Running Loop=1
2021-11-17T18:23:46.109Z,1637173426.109 [Default:CheckIn:D] Stopped
2021-11-17T18:23:46.109Z,1637173426.109 [Default:CheckIn:E] Running Loop=1
2021-11-17T18:23:46.508Z,1637173426.508 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 13.863787 min 
2021-11-17T18:23:46.509Z,1637173426.509 [Default:CheckIn:E] Stopped
2021-11-17T18:23:46.509Z,1637173426.509 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-11-17T18:23:46.509Z,1637173426.509 [Default:CheckIn] Stopped
2021-11-17T18:23:46.509Z,1637173426.509 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-11-17T18:23:46.509Z,1637173426.509 [Default:CheckIn](INFO): Running loop #7
2021-11-17T18:23:46.509Z,1637173426.509 [Default:CheckIn] Running Loop=7
2021-11-17T18:23:46.509Z,1637173426.509 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-11-17T18:23:46.509Z,1637173426.509 [Default:CheckIn:Read_GPS] Running Loop=1
2021-11-17T18:24:46.685Z,1637173486.685 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-11-17T18:23:46.5Z
2021-11-17T18:24:46.685Z,1637173486.685 [Default:CheckIn:Read_GPS] Stopped
2021-11-17T18:24:46.685Z,1637173486.685 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-11-17T18:24:48.405Z,1637173488.405 [DAT](INFO): #Outgoing data=1
2021-11-17T18:24:48.406Z,1637173488.406 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-17T18:24:48.529Z,1637173488.529 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-17T18:24:52.087Z,1637173492.087 [DAT](INFO): DAT read: Forwarding Delay UpTx time:18:24:13.7577

2021-11-17T18:24:52.087Z,1637173492.087 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-17T18:24:54.171Z,1637173494.171 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20211117T180653/Courier0022.lzma
2021-11-17T18:24:55.173Z,1637173495.173 [DataOverHttps](INFO): Moved sent file to Logs/20211117T180653/Courier0022.lzma.bak
2021-11-17T18:24:55.173Z,1637173495.173 [DataOverHttps](INFO): SBD MOMSN=16262019
2021-11-17T18:24:59.369Z,1637173499.369 [DAT](INFO): DAT read: Rx Time:18:24:20.5629

2021-11-17T18:24:59.370Z,1637173499.370 [DAT](INFO): received an acoustic signal
2021-11-17T18:25:00.190Z,1637173500.190 [DAT](INFO): DAT read: 18:24:20.5629 LVL= 32752, 32753, 32754, 32755, AGC= 86, IDX= 491,-0.14, 2.372, 2.451, 2.389, 2.420, PHS=-0.052, 0.075,-0.046, RAW= 327.6,   3.7, CAL= 327.8,   1.8, ROT= 242.2,  -1.8

2021-11-17T18:25:00.211Z,1637173500.211 [DAT](INFO): got valid direction response:
 18:24:20.5629 LVL= 32752, 32753, 32754, 32755, AGC= 86, IDX= 491,-0.14, 2.372, 2.451, 2.389, 2.420, PHS=-0.052, 0.075,-0.046, RAW= 327.6,   3.7, CAL= 327.8,   1.8, ROT= 242.2,  -1.8

2021-11-17T18:25:00.212Z,1637173500.212 [DAT](INFO): DAT read: 

2021-11-17T18:25:00.213Z,1637173500.213 [DAT](INFO): DAT read: DATA(0002):~~

2021-11-17T18:25:00.213Z,1637173500.213 [DAT](INFO): Got DATA 2
2021-11-17T18:25:00.214Z,1637173500.214 [DAT](INFO): DAT read: Source:001  Destination:007

2021-11-17T18:25:00.214Z,1637173500.214 [DAT](INFO): Got Src/Dest after DATA 
2021-11-17T18:25:00.215Z,1637173500.215 [DAT](INFO): DATA Src=1, Dst=7
2021-11-17T18:25:00.215Z,1637173500.215 [DAT](INFO): #Rx 9: Read direction message, but no range.
2021-11-17T18:25:00.217Z,1637173500.217 [DAT](INFO): direction in vehicle frame: [ -0.466157 forward, -0.884144 starboard, -0.031411 keelward ]
2021-11-17T18:25:00.571Z,1637173500.571 [DAT](INFO): DAT read: CRC:Pass MPD:03.8 PSNR:12.4 AGC:87 SPD:-0.1 CCERR:010

2021-11-17T18:25:00.571Z,1637173500.571 [DAT](INFO): Got CRC:Pass
2021-11-17T18:25:00.594Z,1637173500.594 [DAT](INFO): Got CRC:Pass
2021-11-17T18:25:00.594Z,1637173500.594 [DAT](INFO): Incoming data is intended for us
2021-11-17T18:25:00.595Z,1637173500.595 [DAT](DEBUG): In parseResponses, got ack so set commsState_ = SENDING_VERIFIED
2021-11-17T18:25:00.595Z,1637173500.595 [DAT](INFO): Got ack
2021-11-17T18:25:00.595Z,1637173500.595 [DAT](INFO): DAT read: 

2021-11-17T18:25:00.600Z,1637173500.600 [DAT](INFO): DAT read: <EOP>

2021-11-17T18:25:00.600Z,1637173500.600 [DAT](INFO): Sent 39 bytes from file Logs/20211117T180653/Courier0022.lzma.parts
2021-11-17T18:25:00.601Z,1637173500.601 [DAT](INFO): Packets left to send: 0
2021-11-17T18:25:00.603Z,1637173500.603 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-17T18:25:01.994Z,1637173501.994 [Default:CheckIn:Read_Iridium] Stopped
2021-11-17T18:25:01.994Z,1637173501.994 [Default:CheckIn:C.Wait] Running Loop=1
2021-11-17T18:25:01.994Z,1637173501.994 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-11-17T18:25:11.984Z,1637173511.984 [DataOverHttps](INFO): Sending 1107 bytes from file Logs/20211117T180653/Express0001.lzma
2021-11-17T18:25:12.985Z,1637173512.985 [DataOverHttps](INFO): Moved sent file to Logs/20211117T180653/Express0001.lzma.bak
2021-11-17T18:25:12.985Z,1637173512.985 [DataOverHttps](INFO): SBD MOMSN=16262021
2021-11-17T18:26:02.262Z,1637173562.262 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-11-17T18:26:02.263Z,1637173562.263 [Default:CheckIn:C.Wait] Stopped
2021-11-17T18:26:02.263Z,1637173562.263 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-11-17T18:26:02.263Z,1637173562.263 [Default:CheckIn:D] Running Loop=1
2021-11-17T18:26:02.652Z,1637173562.652 [Default:CheckIn:D] Stopped
2021-11-17T18:26:02.652Z,1637173562.652 [Default:CheckIn:E] Running Loop=1
2021-11-17T18:26:03.062Z,1637173563.062 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 16.139496 min 
2021-11-17T18:26:03.062Z,1637173563.062 [Default:CheckIn:E] Stopped
2021-11-17T18:26:03.062Z,1637173563.062 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-11-17T18:26:03.062Z,1637173563.062 [Default:CheckIn] Stopped
2021-11-17T18:26:03.062Z,1637173563.062 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-11-17T18:26:03.063Z,1637173563.063 [Default:CheckIn](INFO): Running loop #8
2021-11-17T18:26:03.063Z,1637173563.063 [Default:CheckIn] Running Loop=8
2021-11-17T18:26:03.063Z,1637173563.063 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-11-17T18:26:03.063Z,1637173563.063 [Default:CheckIn:Read_GPS] Running Loop=1
2021-11-17T18:26:34.132Z,1637173594.132 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2021-11-17T18:27:03.259Z,1637173623.259 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-11-17T18:26:03.1Z
2021-11-17T18:27:03.259Z,1637173623.259 [Default:CheckIn:Read_GPS] Stopped
2021-11-17T18:27:03.259Z,1637173623.259 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-11-17T18:27:04.792Z,1637173624.792 [DAT](INFO): #Outgoing data=1
2021-11-17T18:27:04.793Z,1637173624.793 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-17T18:27:04.886Z,1637173624.886 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-17T18:27:08.482Z,1637173628.482 [DAT](INFO): DAT read: Forwarding Delay UpTx time:18:26:30.1054

2021-11-17T18:27:08.482Z,1637173628.482 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-17T18:27:09.336Z,1637173629.336 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20211117T180653/Courier0025.lzma
2021-11-17T18:27:10.337Z,1637173630.337 [DataOverHttps](INFO): Moved sent file to Logs/20211117T180653/Courier0025.lzma.bak
2021-11-17T18:27:10.337Z,1637173630.337 [DataOverHttps](INFO): SBD MOMSN=16262063
2021-11-17T18:27:15.754Z,1637173635.754 [DAT](INFO): DAT read: Rx Time:18:26:36.9155

2021-11-17T18:27:15.754Z,1637173635.754 [DAT](INFO): received an acoustic signal
2021-11-17T18:27:16.572Z,1637173636.572 [DAT](INFO): DAT read: 18:26:36.9155 LVL= 32752, 32753, 32754, 32755, AGC= 87, IDX= 491, 0.08, 3.094,-3.127, 3.099, 3.112, PHS=-0.022, 0.088,-0.028, RAW= 332.8,  -6.8, CAL= 333.8,  -9.3, ROT= 236.2,   9.3

2021-11-17T18:27:16.573Z,1637173636.573 [DAT](INFO): got valid direction response:
 18:26:36.9155 LVL= 32752, 32753, 32754, 32755, AGC= 87, IDX= 491, 0.08, 3.094,-3.127, 3.099, 3.112, PHS=-0.022, 0.088,-0.028, RAW= 332.8,  -6.8, CAL= 333.8,  -9.3, ROT= 236.2,   9.3

2021-11-17T18:27:16.574Z,1637173636.574 [DAT](INFO): DAT read: 

2021-11-17T18:27:16.574Z,1637173636.574 [DAT](INFO): DAT read: DATA(0002):~~

2021-11-17T18:27:16.575Z,1637173636.575 [DAT](INFO): Got DATA 2
2021-11-17T18:27:16.576Z,1637173636.576 [DAT](INFO): DAT read: Source:001  Destination:007

2021-11-17T18:27:16.576Z,1637173636.576 [DAT](INFO): Got Src/Dest after DATA 
2021-11-17T18:27:16.576Z,1637173636.576 [DAT](INFO): DATA Src=1, Dst=7
2021-11-17T18:27:16.577Z,1637173636.577 [DAT](INFO): #Rx 10: Read direction message, but no range.
2021-11-17T18:27:16.578Z,1637173636.578 [DAT](INFO): direction in vehicle frame: [ -0.548984 forward, -0.820062 starboard, 0.161604 keelward ]
2021-11-17T18:27:16.966Z,1637173636.966 [DAT](INFO): DAT read: CRC:Pass MPD:03.8 PSNR:12.3 AGC:91 SPD:+0.0 CCERR:010

2021-11-17T18:27:16.967Z,1637173636.967 [DAT](INFO): Got CRC:Pass
2021-11-17T18:27:16.967Z,1637173636.967 [DAT](INFO): Got CRC:Pass
2021-11-17T18:27:16.967Z,1637173636.967 [DAT](INFO): Incoming data is intended for us
2021-11-17T18:27:16.967Z,1637173636.967 [DAT](DEBUG): In parseResponses, got ack so set commsState_ = SENDING_VERIFIED
2021-11-17T18:27:16.967Z,1637173636.967 [DAT](INFO): Got ack
2021-11-17T18:27:16.967Z,1637173636.967 [DAT](INFO): DAT read: 

2021-11-17T18:27:16.968Z,1637173636.968 [DAT](INFO): DAT read: <EOP>

2021-11-17T18:27:16.969Z,1637173636.969 [DAT](INFO): Sent 39 bytes from file Logs/20211117T180653/Courier0025.lzma.parts
2021-11-17T18:27:16.969Z,1637173636.969 [DAT](INFO): Packets left to send: 0
2021-11-17T18:27:16.971Z,1637173636.971 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-17T18:27:18.341Z,1637173638.341 [Default:CheckIn:Read_Iridium] Stopped
2021-11-17T18:27:18.342Z,1637173638.342 [Default:CheckIn:C.Wait] Running Loop=1
2021-11-17T18:27:18.342Z,1637173638.342 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-11-17T18:27:28.087Z,1637173648.087 [DataOverHttps](INFO): Sending 105 bytes from file Logs/20211117T180653/Express0005.lzma
2021-11-17T18:27:29.089Z,1637173649.089 [DataOverHttps](INFO): Moved sent file to Logs/20211117T180653/Express0005.lzma.bak
2021-11-17T18:27:29.090Z,1637173649.090 [DataOverHttps](INFO): SBD MOMSN=16262068
2021-11-17T18:27:35.384Z,1637173655.384 [NAL9602](INFO): Not Powering down - fast GPS
2021-11-17T18:28:18.636Z,1637173698.636 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-11-17T18:28:18.637Z,1637173698.637 [Default:CheckIn:C.Wait] Stopped
2021-11-17T18:28:18.637Z,1637173698.637 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-11-17T18:28:18.637Z,1637173698.637 [Default:CheckIn:D] Running Loop=1
2021-11-17T18:28:19.021Z,1637173699.021 [Default:CheckIn:D] Stopped
2021-11-17T18:28:19.021Z,1637173699.021 [Default:CheckIn:E] Running Loop=1
2021-11-17T18:28:19.429Z,1637173699.429 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 18.412323 min 
2021-11-17T18:28:19.429Z,1637173699.429 [Default:CheckIn:E] Stopped
2021-11-17T18:28:19.430Z,1637173699.430 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-11-17T18:28:19.430Z,1637173699.430 [Default:CheckIn] Stopped
2021-11-17T18:28:19.430Z,1637173699.430 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-11-17T18:28:19.430Z,1637173699.430 [Default:CheckIn](INFO): Running loop #9
2021-11-17T18:28:19.430Z,1637173699.430 [Default:CheckIn] Running Loop=9
2021-11-17T18:28:19.430Z,1637173699.430 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-11-17T18:28:19.430Z,1637173699.430 [Default:CheckIn:Read_GPS] Running Loop=1
2021-11-17T18:28:52.137Z,1637173732.137 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2021-11-17T18:28:52.219Z,1637173732.219 [NAL9602](ERROR): received: 
+CSQ:0

OK
2021-11-17T18:29:19.654Z,1637173759.654 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-11-17T18:28:19.4Z
2021-11-17T18:29:19.655Z,1637173759.655 [Default:CheckIn:Read_GPS] Stopped
2021-11-17T18:29:19.655Z,1637173759.655 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-11-17T18:29:20.914Z,1637173760.914 [DAT](INFO): #Outgoing data=1
2021-11-17T18:29:20.914Z,1637173760.914 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-17T18:29:21.044Z,1637173761.044 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-17T18:29:24.633Z,1637173764.633 [DAT](INFO): DAT read: Forwarding Delay UpTx time:18:28:46.2533

2021-11-17T18:29:24.633Z,1637173764.633 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-17T18:29:27.515Z,1637173767.515 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20211117T180653/Courier0028.lzma
2021-11-17T18:29:28.517Z,1637173768.517 [DataOverHttps](INFO): Moved sent file to Logs/20211117T180653/Courier0028.lzma.bak
2021-11-17T18:29:28.518Z,1637173768.518 [DataOverHttps](INFO): SBD MOMSN=16262074
2021-11-17T18:29:31.896Z,1637173771.896 [DAT](INFO): DAT read: Rx Time:18:28:53.1180

2021-11-17T18:29:31.897Z,1637173771.897 [DAT](INFO): received an acoustic signal
2021-11-17T18:29:32.728Z,1637173772.728 [DAT](INFO): DAT read: 18:28:53.1180 LVL= 32752, 32753, 32754, 32755, AGC= 86, IDX= 491, 0.15,-2.463,-2.391,-2.447,-2.423, PHS=-0.044, 0.076,-0.040, RAW= 328.2,   1.4, CAL= 328.5,  -0.9, ROT= 241.5,   0.9

2021-11-17T18:29:32.729Z,1637173772.729 [DAT](INFO): got valid direction response:
 18:28:53.1180 LVL= 32752, 32753, 32754, 32755, AGC= 86, IDX= 491, 0.15,-2.463,-2.391,-2.447,-2.423, PHS=-0.044, 0.076,-0.040, RAW= 328.2,   1.4, CAL= 328.5,  -0.9, ROT= 241.5,   0.9

2021-11-17T18:29:32.729Z,1637173772.729 [DAT](INFO): DAT read: 

2021-11-17T18:29:32.730Z,1637173772.730 [DAT](INFO): DAT read: DATA(0002):~~

2021-11-17T18:29:32.730Z,1637173772.730 [DAT](INFO): Got DATA 2
2021-11-17T18:29:32.731Z,1637173772.731 [DAT](INFO): #Rx 11: Read direction message, but no range.
2021-11-17T18:29:32.733Z,1637173772.733 [DAT](INFO): direction in vehicle frame: [ -0.477100 forward, -0.878709 starboard, 0.015707 keelward ]
2021-11-17T18:29:33.107Z,1637173773.107 [DAT](INFO): DAT read: Source:001  Destination:007

2021-11-17T18:29:33.108Z,1637173773.108 [DAT](INFO): Got Src/Dest after DATA 
2021-11-17T18:29:33.108Z,1637173773.108 [DAT](INFO): DATA Src=1, Dst=7
2021-11-17T18:29:33.109Z,1637173773.109 [DAT](INFO): DAT read: CRC:Pass MPD:03.8 PSNR:12.1 AGC:88 SPD:+0.0 CCERR:010

2021-11-17T18:29:33.109Z,1637173773.109 [DAT](INFO): Got CRC:Pass
2021-11-17T18:29:33.110Z,1637173773.110 [DAT](INFO): Got CRC:Pass
2021-11-17T18:29:33.110Z,1637173773.110 [DAT](INFO): Incoming data is intended for us
2021-11-17T18:29:33.110Z,1637173773.110 [DAT](DEBUG): In parseResponses, got ack so set commsState_ = SENDING_VERIFIED
2021-11-17T18:29:33.110Z,1637173773.110 [DAT](INFO): Got ack
2021-11-17T18:29:33.110Z,1637173773.110 [DAT](INFO): DAT read: 

2021-11-17T18:29:33.111Z,1637173773.111 [DAT](INFO): DAT read: <EOP>

2021-11-17T18:29:33.115Z,1637173773.115 [DAT](INFO): Sent 39 bytes from file Logs/20211117T180653/Courier0028.lzma.parts
2021-11-17T18:29:33.116Z,1637173773.116 [DAT](INFO): Packets left to send: 0
2021-11-17T18:29:33.118Z,1637173773.118 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-17T18:29:34.522Z,1637173774.522 [Default:CheckIn:Read_Iridium] Stopped
2021-11-17T18:29:34.522Z,1637173774.522 [Default:CheckIn:C.Wait] Running Loop=1
2021-11-17T18:29:34.522Z,1637173774.522 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-11-17T18:29:46.991Z,1637173786.991 [DataOverHttps](INFO): Sending 251 bytes from file Logs/20211117T180653/Express0008.lzma
2021-11-17T18:29:47.993Z,1637173787.993 [DataOverHttps](INFO): Moved sent file to Logs/20211117T180653/Express0008.lzma.bak
2021-11-17T18:29:47.993Z,1637173787.993 [DataOverHttps](INFO): SBD MOMSN=16262076
2021-11-17T18:30:34.778Z,1637173834.778 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-11-17T18:30:34.778Z,1637173834.778 [Default:CheckIn:C.Wait] Stopped
2021-11-17T18:30:34.778Z,1637173834.778 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-11-17T18:30:34.778Z,1637173834.778 [Default:CheckIn:D] Running Loop=1
2021-11-17T18:30:35.185Z,1637173835.185 [Default:CheckIn:D] Stopped
2021-11-17T18:30:35.185Z,1637173835.185 [Default:CheckIn:E] Running Loop=1
2021-11-17T18:30:35.595Z,1637173835.595 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 20.681732 min 
2021-11-17T18:30:35.595Z,1637173835.595 [Default:CheckIn:E] Stopped
2021-11-17T18:30:35.595Z,1637173835.595 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-11-17T18:30:35.595Z,1637173835.595 [Default:CheckIn] Stopped
2021-11-17T18:30:35.595Z,1637173835.595 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-11-17T18:30:35.595Z,1637173835.595 [Default:CheckIn](INFO): Running loop #10
2021-11-17T18:30:35.596Z,1637173835.596 [Default:CheckIn] Running Loop=10
2021-11-17T18:30:35.596Z,1637173835.596 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-11-17T18:30:35.596Z,1637173835.596 [Default:CheckIn:Read_GPS] Running Loop=1
2021-11-17T18:31:35.792Z,1637173895.792 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-11-17T18:30:35.6Z
2021-11-17T18:31:35.792Z,1637173895.792 [Default:CheckIn:Read_GPS] Stopped
2021-11-17T18:31:35.792Z,1637173895.792 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-11-17T18:31:37.405Z,1637173897.405 [DAT](INFO): #Outgoing data=1
2021-11-17T18:31:37.405Z,1637173897.405 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-17T18:31:37.515Z,1637173897.515 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-17T18:31:41.118Z,1637173901.118 [DAT](INFO): DAT read: Forwarding Delay UpTx time:18:31:02.7511

2021-11-17T18:31:41.118Z,1637173901.118 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-17T18:31:42.927Z,1637173902.927 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20211117T180653/Courier0031.lzma
2021-11-17T18:31:43.929Z,1637173903.929 [DataOverHttps](INFO): Moved sent file to Logs/20211117T180653/Courier0031.lzma.bak
2021-11-17T18:31:43.929Z,1637173903.929 [DataOverHttps](INFO): SBD MOMSN=16262081
2021-11-17T18:31:48.386Z,1637173908.386 [DAT](INFO): DAT read: Rx Time:18:31:09.5207

2021-11-17T18:31:48.386Z,1637173908.386 [DAT](INFO): received an acoustic signal
2021-11-17T18:31:49.197Z,1637173909.197 [DAT](INFO): DAT read: 18:31:09.5206 LVL= 32752, 32753, 32754, 32755, AGC= 86, IDX= 492,-0.48, 2.315, 2.388, 2.330, 2.357, PHS=-0.045, 0.076,-0.042, RAW= 328.5,   1.9, CAL= 328.7,  -0.4, ROT= 241.3,   0.4

2021-11-17T18:31:49.198Z,1637173909.198 [DAT](INFO): got valid direction response:
 18:31:09.5206 LVL= 32752, 32753, 32754, 32755, AGC= 86, IDX= 492,-0.48, 2.315, 2.388, 2.330, 2.357, PHS=-0.045, 0.076,-0.042, RAW= 328.5,   1.9, CAL= 328.7,  -0.4, ROT= 241.3,   0.4

2021-11-17T18:31:49.198Z,1637173909.198 [DAT](INFO): DAT read: 

2021-11-17T18:31:49.199Z,1637173909.199 [DAT](INFO): DAT read: DATA(0002):~~

2021-11-17T18:31:49.200Z,1637173909.200 [DAT](INFO): Got DATA 2
2021-11-17T18:31:49.201Z,1637173909.201 [DAT](INFO): DAT read: Source:001  Destination:007

2021-11-17T18:31:49.201Z,1637173909.201 [DAT](INFO): Got Src/Dest after DATA 
2021-11-17T18:31:49.201Z,1637173909.201 [DAT](INFO): DATA Src=1, Dst=7
2021-11-17T18:31:49.203Z,1637173909.203 [DAT](INFO): DAT read: CRC:Pass MPD:03.8 PSNR:12.1 AGC:87 SPD:-0.1 CCERR:010

2021-11-17T18:31:49.203Z,1637173909.203 [DAT](INFO): Got CRC:Pass
2021-11-17T18:31:49.203Z,1637173909.203 [DAT](INFO): Got CRC:Pass
2021-11-17T18:31:49.203Z,1637173909.203 [DAT](INFO): Incoming data is intended for us
2021-11-17T18:31:49.203Z,1637173909.203 [DAT](DEBUG): In parseResponses, got ack so set commsState_ = SENDING_VERIFIED
2021-11-17T18:31:49.203Z,1637173909.203 [DAT](INFO): Got ack
2021-11-17T18:31:49.204Z,1637173909.204 [DAT](INFO): DAT read: 

2021-11-17T18:31:49.204Z,1637173909.204 [DAT](INFO): DAT read: <EOP>

2021-11-17T18:31:49.205Z,1637173909.205 [DAT](INFO): Sent 39 bytes from file Logs/20211117T180653/Courier0031.lzma.parts
2021-11-17T18:31:49.205Z,1637173909.205 [DAT](INFO): Packets left to send: 0
2021-11-17T18:31:49.259Z,1637173909.259 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-17T18:31:49.268Z,1637173909.268 [DAT](INFO): #Rx 12: Read direction message, but no range.
2021-11-17T18:31:49.269Z,1637173909.269 [DAT](INFO): direction in vehicle frame: [ -0.480212 forward, -0.877125 starboard, 0.006981 keelward ]
2021-11-17T18:31:50.598Z,1637173910.598 [Default:CheckIn:Read_Iridium] Stopped
2021-11-17T18:31:50.598Z,1637173910.598 [Default:CheckIn:C.Wait] Running Loop=1
2021-11-17T18:31:50.598Z,1637173910.598 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-11-17T18:32:01.655Z,1637173921.655 [DataOverHttps](INFO): Sending 133 bytes from file Logs/20211117T180653/Express0011.lzma
2021-11-17T18:32:02.657Z,1637173922.657 [DataOverHttps](INFO): Moved sent file to Logs/20211117T180653/Express0011.lzma.bak
2021-11-17T18:32:02.657Z,1637173922.657 [DataOverHttps](INFO): SBD MOMSN=16262084
2021-11-17T18:32:50.887Z,1637173970.887 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-11-17T18:32:50.888Z,1637173970.888 [Default:CheckIn:C.Wait] Stopped
2021-11-17T18:32:50.888Z,1637173970.888 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-11-17T18:32:50.888Z,1637173970.888 [Default:CheckIn:D] Running Loop=1
2021-11-17T18:32:51.281Z,1637173971.281 [Default:CheckIn:D] Stopped
2021-11-17T18:32:51.281Z,1637173971.281 [Default:CheckIn:E] Running Loop=1
2021-11-17T18:32:51.682Z,1637173971.682 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 22.949986 min 
2021-11-17T18:32:51.682Z,1637173971.682 [Default:CheckIn:E] Stopped
2021-11-17T18:32:51.682Z,1637173971.682 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-11-17T18:32:51.682Z,1637173971.682 [Default:CheckIn] Stopped
2021-11-17T18:32:51.683Z,1637173971.683 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-11-17T18:32:51.683Z,1637173971.683 [Default:CheckIn](INFO): Running loop #11
2021-11-17T18:32:51.683Z,1637173971.683 [Default:CheckIn] Running Loop=11
2021-11-17T18:32:51.683Z,1637173971.683 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-11-17T18:32:51.683Z,1637173971.683 [Default:CheckIn:Read_GPS] Running Loop=1
2021-11-17T18:33:23.182Z,1637174003.182 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2021-11-17T18:33:23.989Z,1637174003.989 [NAL9602](FAULT): GPS failed to acquire within timeout.
2021-11-17T18:33:23.989Z,1637174003.989 [NAL9602] Data Fault, FailCount= 1
2021-11-17T18:33:23.989Z,1637174003.989 [NAL9602](ERROR): Data Fault
2021-11-17T18:33:24.043Z,1637174004.043 [CBIT](ERROR): Data Fault in component: NAL9602
2021-11-17T18:33:24.393Z,1637174004.393 [NAL9602](INFO): Powering down
2021-11-17T18:33:25.248Z,1637174005.248 [CBIT](INFO): Clearing failed state for component NAL9602
2021-11-17T18:33:25.248Z,1637174005.248 [NAL9602] No Fault, FailCount= 1
2021-11-17T18:33:51.896Z,1637174031.896 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-11-17T18:32:51.7Z
2021-11-17T18:33:51.897Z,1637174031.897 [Default:CheckIn:Read_GPS] Stopped
2021-11-17T18:33:51.897Z,1637174031.897 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-11-17T18:33:53.436Z,1637174033.436 [DAT](INFO): #Outgoing data=1
2021-11-17T18:33:53.436Z,1637174033.436 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-17T18:33:53.530Z,1637174033.530 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-17T18:33:54.685Z,1637174034.685 [NAL9602](INFO): Powering up NAL9602
2021-11-17T18:33:57.110Z,1637174037.110 [DAT](INFO): DAT read: Forwarding Delay UpTx time:18:33:18.7489

2021-11-17T18:33:57.110Z,1637174037.110 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-17T18:33:58.959Z,1637174038.959 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20211117T180653/Courier0034.lzma
2021-11-17T18:33:59.961Z,1637174039.961 [DataOverHttps](INFO): Moved sent file to Logs/20211117T180653/Courier0034.lzma.bak
2021-11-17T18:33:59.962Z,1637174039.962 [DataOverHttps](INFO): SBD MOMSN=16262107
2021-11-17T18:34:04.382Z,1637174044.382 [DAT](INFO): DAT read: Rx Time:18:33:25.5241

2021-11-17T18:34:04.383Z,1637174044.383 [DAT](INFO): received an acoustic signal
2021-11-17T18:34:05.215Z,1637174045.215 [DAT](INFO): DAT read: 18:33:25.5241 LVL= 32752, 32753, 32754, 32755, AGC= 86, IDX= 502,-0.40, 1.432, 1.508, 1.446, 1.477, PHS=-0.048, 0.076,-0.045, RAW= 328.7,   2.9, CAL= 328.9,   0.8, ROT= 241.1,  -0.8

2021-11-17T18:34:05.220Z,1637174045.220 [DAT](INFO): got valid direction response:
 18:33:25.5241 LVL= 32752, 32753, 32754, 32755, AGC= 86, IDX= 502,-0.40, 1.432, 1.508, 1.446, 1.477, PHS=-0.048, 0.076,-0.045, RAW= 328.7,   2.9, CAL= 328.9,   0.8, ROT= 241.1,  -0.8

2021-11-17T18:34:05.221Z,1637174045.221 [DAT](INFO): DAT read: 

2021-11-17T18:34:05.222Z,1637174045.222 [DAT](INFO): DAT read: DATA(0002):~~

2021-11-17T18:34:05.222Z,1637174045.222 [DAT](INFO): Got DATA 2
2021-11-17T18:34:05.223Z,1637174045.223 [DAT](INFO): DAT read: Source:001  Destination:007

2021-11-17T18:34:05.223Z,1637174045.223 [DAT](INFO): Got Src/Dest after DATA 
2021-11-17T18:34:05.227Z,1637174045.227 [DAT](INFO): DATA Src=1, Dst=7
2021-11-17T18:34:05.229Z,1637174045.229 [DAT](INFO): DAT read: CRC:Pass MPD:02.6 PSNR:12.5 AGC:89 SPD:+0.0 CCERR:010

2021-11-17T18:34:05.229Z,1637174045.229 [DAT](INFO): Got CRC:Pass
2021-11-17T18:34:05.229Z,1637174045.229 [DAT](INFO): Got CRC:Pass
2021-11-17T18:34:05.229Z,1637174045.229 [DAT](INFO): Incoming data is intended for us
2021-11-17T18:34:05.229Z,1637174045.229 [DAT](DEBUG): In parseResponses, got ack so set commsState_ = SENDING_VERIFIED
2021-11-17T18:34:05.229Z,1637174045.229 [DAT](INFO): Got ack
2021-11-17T18:34:05.230Z,1637174045.230 [DAT](INFO): DAT read: 

2021-11-17T18:34:05.230Z,1637174045.230 [DAT](INFO): DAT read: <EOP>

2021-11-17T18:34:05.231Z,1637174045.231 [DAT](INFO): Sent 39 bytes from file Logs/20211117T180653/Courier0034.lzma.parts
2021-11-17T18:34:05.231Z,1637174045.231 [DAT](INFO): Packets left to send: 0
2021-11-17T18:34:05.237Z,1637174045.237 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-17T18:34:05.238Z,1637174045.238 [DAT](INFO): #Rx 13: Read direction message, but no range.
2021-11-17T18:34:05.239Z,1637174045.239 [DAT](INFO): direction in vehicle frame: [ -0.483235 forward, -0.875379 starboard, -0.013962 keelward ]
2021-11-17T18:34:05.597Z,1637174045.597 [NAL9602](INFO): NAL9602 initialized
2021-11-17T18:34:06.591Z,1637174046.591 [Default:CheckIn:Read_Iridium] Stopped
2021-11-17T18:34:06.591Z,1637174046.591 [Default:CheckIn:C.Wait] Running Loop=1
2021-11-17T18:34:06.591Z,1637174046.591 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-11-17T18:34:17.619Z,1637174057.619 [DataOverHttps](INFO): Sending 129 bytes from file Logs/20211117T180653/Express0014.lzma
2021-11-17T18:34:18.621Z,1637174058.621 [DataOverHttps](INFO): Moved sent file to Logs/20211117T180653/Express0014.lzma.bak
2021-11-17T18:34:18.621Z,1637174058.621 [DataOverHttps](INFO): SBD MOMSN=16262111
2021-11-17T18:34:37.373Z,1637174077.373 [NAL9602](INFO): Not Powering down - fast GPS
2021-11-17T18:35:06.880Z,1637174106.880 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-11-17T18:35:06.880Z,1637174106.880 [Default:CheckIn:C.Wait] Stopped
2021-11-17T18:35:06.880Z,1637174106.880 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-11-17T18:35:06.880Z,1637174106.880 [Default:CheckIn:D] Running Loop=1
2021-11-17T18:35:07.294Z,1637174107.294 [Default:CheckIn:D] Stopped
2021-11-17T18:35:07.294Z,1637174107.294 [Default:CheckIn:E] Running Loop=1
2021-11-17T18:35:07.689Z,1637174107.689 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 25.216868 min 
2021-11-17T18:35:07.689Z,1637174107.689 [Default:CheckIn:E] Stopped
2021-11-17T18:35:07.690Z,1637174107.690 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-11-17T18:35:07.690Z,1637174107.690 [Default:CheckIn] Stopped
2021-11-17T18:35:07.690Z,1637174107.690 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-11-17T18:35:07.690Z,1637174107.690 [Default:CheckIn](INFO): Running loop #12
2021-11-17T18:35:07.690Z,1637174107.690 [Default:CheckIn] Running Loop=12
2021-11-17T18:35:07.690Z,1637174107.690 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-11-17T18:35:07.690Z,1637174107.690 [Default:CheckIn:Read_GPS] Running Loop=1
2021-11-17T18:36:07.894Z,1637174167.894 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-11-17T18:35:07.7Z
2021-11-17T18:36:07.894Z,1637174167.894 [Default:CheckIn:Read_GPS] Stopped
2021-11-17T18:36:07.895Z,1637174167.895 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-11-17T18:36:09.449Z,1637174169.449 [DAT](INFO): #Outgoing data=1
2021-11-17T18:36:09.449Z,1637174169.449 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-17T18:36:09.565Z,1637174169.565 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-17T18:36:13.175Z,1637174173.175 [DAT](INFO): DAT read: Forwarding Delay UpTx time:18:35:34.7968

2021-11-17T18:36:13.175Z,1637174173.175 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-17T18:36:15.103Z,1637174175.103 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20211117T180653/Courier0037.lzma
2021-11-17T18:36:16.105Z,1637174176.105 [DataOverHttps](INFO): Moved sent file to Logs/20211117T180653/Courier0037.lzma.bak
2021-11-17T18:36:16.105Z,1637174176.105 [DataOverHttps](INFO): SBD MOMSN=16262125
2021-11-17T18:36:20.457Z,1637174180.457 [DAT](INFO): DAT read: Rx Time:18:35:41.5755

2021-11-17T18:36:20.457Z,1637174180.457 [DAT](INFO): received an acoustic signal
2021-11-17T18:36:21.279Z,1637174181.279 [DAT](INFO): DAT read: 18:35:41.5755 LVL= 32752, 32753, 32754, 32755, AGC= 86, IDX= 475,-0.25, 1.686, 1.762, 1.703, 1.729, PHS=-0.048, 0.076,-0.041, RAW= 327.2,   2.1, CAL= 327.4,  -0.2, ROT= 242.6,   0.2

2021-11-17T18:36:21.280Z,1637174181.280 [DAT](INFO): got valid direction response:
 18:35:41.5755 LVL= 32752, 32753, 32754, 32755, AGC= 86, IDX= 475,-0.25, 1.686, 1.762, 1.703, 1.729, PHS=-0.048, 0.076,-0.041, RAW= 327.2,   2.1, CAL= 327.4,  -0.2, ROT= 242.6,   0.2

2021-11-17T18:36:21.281Z,1637174181.281 [DAT](INFO): DAT read: 

2021-11-17T18:36:21.281Z,1637174181.281 [DAT](INFO): DAT read: DATA(0002):~~

2021-11-17T18:36:21.282Z,1637174181.282 [DAT](INFO): Got DATA 2
2021-11-17T18:36:21.282Z,1637174181.282 [DAT](INFO): DAT read: Source:001  Destination:007

2021-11-17T18:36:21.283Z,1637174181.283 [DAT](INFO): Got Src/Dest after DATA 
2021-11-17T18:36:21.283Z,1637174181.283 [DAT](INFO): DATA Src=1, Dst=7
2021-11-17T18:36:21.289Z,1637174181.289 [DAT](INFO): DAT read: CRC:Pass MPD:03.8 PSNR:12.1 AGC:88 SPD:+0.0 CCERR:010

2021-11-17T18:36:21.289Z,1637174181.289 [DAT](INFO): Got CRC:Pass
2021-11-17T18:36:21.289Z,1637174181.289 [DAT](INFO): Got CRC:Pass
2021-11-17T18:36:21.289Z,1637174181.289 [DAT](INFO): Incoming data is intended for us
2021-11-17T18:36:21.289Z,1637174181.289 [DAT](DEBUG): In parseResponses, got ack so set commsState_ = SENDING_VERIFIED
2021-11-17T18:36:21.289Z,1637174181.289 [DAT](INFO): Got ack
2021-11-17T18:36:21.290Z,1637174181.290 [DAT](INFO): DAT read: 

2021-11-17T18:36:21.290Z,1637174181.290 [DAT](INFO): DAT read: <EOP>

2021-11-17T18:36:21.291Z,1637174181.291 [DAT](INFO): Sent 39 bytes from file Logs/20211117T180653/Courier0037.lzma.parts
2021-11-17T18:36:21.291Z,1637174181.291 [DAT](INFO): Packets left to send: 0
2021-11-17T18:36:21.340Z,1637174181.340 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-17T18:36:21.341Z,1637174181.341 [DAT](INFO): #Rx 14: Read direction message, but no range.
2021-11-17T18:36:21.342Z,1637174181.342 [DAT](INFO): direction in vehicle frame: [ -0.460197 forward, -0.887810 starboard, 0.003491 keelward ]
2021-11-17T18:36:22.646Z,1637174182.646 [Default:CheckIn:Read_Iridium] Stopped
2021-11-17T18:36:22.646Z,1637174182.646 [Default:CheckIn:C.Wait] Running Loop=1
2021-11-17T18:36:22.646Z,1637174182.646 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-11-17T18:36:33.963Z,1637174193.963 [DataOverHttps](INFO): Sending 221 bytes from file Logs/20211117T180653/Express0017.lzma
2021-11-17T18:36:34.965Z,1637174194.965 [DataOverHttps](INFO): Moved sent file to Logs/20211117T180653/Express0017.lzma.bak
2021-11-17T18:36:34.965Z,1637174194.965 [DataOverHttps](INFO): SBD MOMSN=16262132
2021-11-17T18:37:22.938Z,1637174242.938 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-11-17T18:37:22.939Z,1637174242.939 [Default:CheckIn:C.Wait] Stopped
2021-11-17T18:37:22.939Z,1637174242.939 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-11-17T18:37:22.939Z,1637174242.939 [Default:CheckIn:D] Running Loop=1
2021-11-17T18:37:23.356Z,1637174243.356 [Default:CheckIn:D] Stopped
2021-11-17T18:37:23.356Z,1637174243.356 [Default:CheckIn:E] Running Loop=1
2021-11-17T18:37:23.746Z,1637174243.746 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 27.484572 min 
2021-11-17T18:37:23.746Z,1637174243.746 [Default:CheckIn:E] Stopped
2021-11-17T18:37:23.746Z,1637174243.746 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-11-17T18:37:23.746Z,1637174243.746 [Default:CheckIn] Stopped
2021-11-17T18:37:23.746Z,1637174243.746 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-11-17T18:37:23.747Z,1637174243.747 [Default:CheckIn](INFO): Running loop #13
2021-11-17T18:37:23.747Z,1637174243.747 [Default:CheckIn] Running Loop=13
2021-11-17T18:37:23.747Z,1637174243.747 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-11-17T18:37:23.747Z,1637174243.747 [Default:CheckIn:Read_GPS] Running Loop=1
2021-11-17T18:38:23.933Z,1637174303.933 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-11-17T18:37:23.7Z
2021-11-17T18:38:23.933Z,1637174303.933 [Default:CheckIn:Read_GPS] Stopped
2021-11-17T18:38:23.934Z,1637174303.934 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-11-17T18:38:25.589Z,1637174305.589 [DAT](INFO): #Outgoing data=1
2021-11-17T18:38:25.590Z,1637174305.590 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-17T18:38:25.729Z,1637174305.729 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-17T18:38:29.337Z,1637174309.337 [DAT](INFO): DAT read: Forwarding Delay UpTx time:18:37:50.9446

2021-11-17T18:38:29.337Z,1637174309.337 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-17T18:38:31.407Z,1637174311.407 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20211117T180653/Courier0040.lzma
2021-11-17T18:38:32.409Z,1637174312.409 [DataOverHttps](INFO): Moved sent file to Logs/20211117T180653/Courier0040.lzma.bak
2021-11-17T18:38:32.409Z,1637174312.409 [DataOverHttps](INFO): SBD MOMSN=16262139
2021-11-17T18:38:36.617Z,1637174316.617 [DAT](INFO): DAT read: Rx Time:18:37:57.7781

2021-11-17T18:38:36.617Z,1637174316.617 [DAT](INFO): received an acoustic signal
2021-11-17T18:38:37.439Z,1637174317.439 [DAT](INFO): DAT read: 18:37:57.7781 LVL= 32752, 32753, 32754, 32755, AGC= 87, IDX= 491,-0.12, 1.359, 1.423, 1.364, 1.377, PHS=-0.022, 0.091,-0.027, RAW= 332.2,  -7.3, CAL= 333.3,  -9.7, ROT= 236.7,   9.7

2021-11-17T18:38:37.440Z,1637174317.440 [DAT](INFO): got valid direction response:
 18:37:57.7781 LVL= 32752, 32753, 32754, 32755, AGC= 87, IDX= 491,-0.12, 1.359, 1.423, 1.364, 1.377, PHS=-0.022, 0.091,-0.027, RAW= 332.2,  -7.3, CAL= 333.3,  -9.7, ROT= 236.7,   9.7

2021-11-17T18:38:37.441Z,1637174317.441 [DAT](INFO): DAT read: 

2021-11-17T18:38:37.442Z,1637174317.442 [DAT](INFO): DAT read: DATA(0002):~~

2021-11-17T18:38:37.442Z,1637174317.442 [DAT](INFO): Got DATA 2
2021-11-17T18:38:37.443Z,1637174317.443 [DAT](INFO): DAT read: Source:001  Destination:007

2021-11-17T18:38:37.443Z,1637174317.443 [DAT](INFO): Got Src/Dest after DATA 
2021-11-17T18:38:37.444Z,1637174317.444 [DAT](INFO): DATA Src=1, Dst=7
2021-11-17T18:38:37.445Z,1637174317.445 [DAT](INFO): #Rx 15: Read direction message, but no range.
2021-11-17T18:38:37.446Z,1637174317.446 [DAT](INFO): direction in vehicle frame: [ -0.541174 forward, -0.823858 starboard, 0.168489 keelward ]
2021-11-17T18:38:37.819Z,1637174317.819 [DAT](INFO): DAT read: CRC:Pass MPD:03.5 PSNR:12.5 AGC:90 SPD:-0.1 CCERR:010

2021-11-17T18:38:37.819Z,1637174317.819 [DAT](INFO): Got CRC:Pass
2021-11-17T18:38:37.819Z,1637174317.819 [DAT](INFO): Got CRC:Pass
2021-11-17T18:38:37.819Z,1637174317.819 [DAT](INFO): Incoming data is intended for us
2021-11-17T18:38:37.819Z,1637174317.819 [DAT](DEBUG): In parseResponses, got ack so set commsState_ = SENDING_VERIFIED
2021-11-17T18:38:37.820Z,1637174317.820 [DAT](INFO): Got ack
2021-11-17T18:38:37.820Z,1637174317.820 [DAT](INFO): DAT read: 

2021-11-17T18:38:37.820Z,1637174317.820 [DAT](INFO): DAT read: <EOP>

2021-11-17T18:38:37.821Z,1637174317.821 [DAT](INFO): Sent 39 bytes from file Logs/20211117T180653/Courier0040.lzma.parts
2021-11-17T18:38:37.821Z,1637174317.821 [DAT](INFO): Packets left to send: 0
2021-11-17T18:38:37.828Z,1637174317.828 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-17T18:38:39.392Z,1637174319.392 [Default:CheckIn:Read_Iridium] Stopped
2021-11-17T18:38:39.392Z,1637174319.392 [Default:CheckIn:C.Wait] Running Loop=1
2021-11-17T18:38:39.392Z,1637174319.392 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-11-17T18:38:50.667Z,1637174330.667 [DataOverHttps](INFO): Sending 130 bytes from file Logs/20211117T180653/Express0020.lzma
2021-11-17T18:38:51.669Z,1637174331.669 [DataOverHttps](INFO): Moved sent file to Logs/20211117T180653/Express0020.lzma.bak
2021-11-17T18:38:51.669Z,1637174331.669 [DataOverHttps](INFO): SBD MOMSN=16262141
2021-11-17T18:39:27.900Z,1637174367.900 [CommandExec](IMPORTANT): got command configSet DataOverHttps.loadAtStartup 0.000000 bool persist
2021-11-17T18:39:27.901Z,1637174367.901 [CommandExec](IMPORTANT): configSet DataOverHttps.loadAtStartup requires a restart to take effect.
2021-11-17T18:39:39.693Z,1637174379.693 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-11-17T18:39:39.693Z,1637174379.693 [Default:CheckIn:C.Wait] Stopped
2021-11-17T18:39:39.693Z,1637174379.693 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-11-17T18:39:39.693Z,1637174379.693 [Default:CheckIn:D] Running Loop=1
2021-11-17T18:39:40.083Z,1637174380.083 [Default:CheckIn:D] Stopped
2021-11-17T18:39:40.084Z,1637174380.084 [Default:CheckIn:E] Running Loop=1
2021-11-17T18:39:40.498Z,1637174380.498 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 29.763363 min 
2021-11-17T18:39:40.498Z,1637174380.498 [Default:CheckIn:E] Stopped
2021-11-17T18:39:40.498Z,1637174380.498 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-11-17T18:39:40.498Z,1637174380.498 [Default:CheckIn] Stopped
2021-11-17T18:39:40.498Z,1637174380.498 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-11-17T18:39:40.499Z,1637174380.499 [Default:CheckIn](INFO): Running loop #14
2021-11-17T18:39:40.499Z,1637174380.499 [Default:CheckIn] Running Loop=14
2021-11-17T18:39:40.499Z,1637174380.499 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-11-17T18:39:40.499Z,1637174380.499 [Default:CheckIn:Read_GPS] Running Loop=1
2021-11-17T18:40:11.973Z,1637174411.973 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2021-11-17T18:40:17.717Z,1637174417.717 [CommandExec](IMPORTANT): got command restart application
2021-11-17T18:40:18.719Z,1637174418.719 [CommandExec ThreadHandler](INFO): Uninitializing protected caller thread.
2021-11-17T18:40:18.720Z,1637174418.720 [CommandExec](INFO): Uninitializing the command executive.
2021-11-17T18:40:18.720Z,1637174418.720 [CommandExec](INFO): Uninitializing the command scheduler.
2021-11-17T18:40:18.720Z,1637174418.720 [CommandExec ThreadHandler](INFO): Thread cancelled.
2021-11-17T18:40:18.803Z,1637174418.803 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2021-11-17T18:40:18.803Z,1637174418.803 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2021-11-17T18:40:18.804Z,1637174418.804 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2021-11-17T18:40:18.807Z,1637174418.807 [NavChartDb](INFO): Join timeout helper Thread ID is 7720
2021-11-17T18:40:19.135Z,1637174419.135 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2021-11-17T18:40:19.136Z,1637174419.136 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2021-11-17T18:40:19.143Z,1637174419.143 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2021-11-17T18:40:19.143Z,1637174419.143 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2021-11-17T18:40:19.144Z,1637174419.144 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 7721
2021-11-17T18:40:19.616Z,1637174419.616 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread.
2021-11-17T18:40:19.616Z,1637174419.616 [WetLabsBB2FL](INFO): Powering down
2021-11-17T18:40:19.619Z,1637174419.619 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2021-11-17T18:40:19.629Z,1637174419.629 [ComponentRegistry](INFO): Shutting down CTD_Seabird ThreadHandler
2021-11-17T18:40:19.629Z,1637174419.629 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2021-11-17T18:40:19.630Z,1637174419.630 [CTD_Seabird](INFO): Join timeout helper Thread ID is 7722
2021-11-17T18:40:20.352Z,1637174420.352 [CTD_Seabird](INFO): Powering down
2021-11-17T18:40:20.364Z,1637174420.364 [CTD_Seabird ThreadHandler](INFO): Uninitializing protected caller thread.
2021-11-17T18:40:20.364Z,1637174420.364 [CTD_Seabird](INFO): Powering down
2021-11-17T18:40:20.380Z,1637174420.380 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2021-11-17T18:40:20.388Z,1637174420.388 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2021-11-17T18:40:20.388Z,1637174420.388 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2021-11-17T18:40:20.388Z,1637174420.388 [Radio_Surface](INFO): Join timeout helper Thread ID is 7723
2021-11-17T18:40:20.764Z,1637174420.764 [Radio_Surface](INFO): Powering down
2021-11-17T18:40:20.765Z,1637174420.765 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2021-11-17T18:40:20.765Z,1637174420.765 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2021-11-17T18:40:20.768Z,1637174420.768 [ComponentRegistry](INFO): Shutting down Onboard ThreadHandler
2021-11-17T18:40:20.768Z,1637174420.768 [Onboard ThreadHandler](INFO): Thread cancelled.
2021-11-17T18:40:20.768Z,1637174420.768 [Onboard](INFO): Join timeout helper Thread ID is 7724
2021-11-17T18:40:21.744Z,1637174421.744 [Onboard ThreadHandler](INFO): Uninitializing protected caller thread.
2021-11-17T18:40:21.744Z,1637174421.744 [Onboard ThreadHandler](INFO): Thread cancelled.
2021-11-17T18:40:21.752Z,1637174421.752 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2021-11-17T18:40:21.752Z,1637174421.752 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2021-11-17T18:40:21.753Z,1637174421.753 [DataOverHttps](INFO): Join timeout helper Thread ID is 7725
2021-11-17T18:40:23.364Z,1637174423.364 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2021-11-17T18:40:23.367Z,1637174423.367 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2021-11-17T18:40:23.372Z,1637174423.372 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2021-11-17T18:40:23.372Z,1637174423.372 [logger ThreadHandler](INFO): Thread cancelled.
2021-11-17T18:40:23.373Z,1637174423.373 [logger](INFO): Join timeout helper Thread ID is 7726
2021-11-17T18:40:23.388Z,1637174423.388 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2021-11-17T18:40:23.388Z,1637174423.388 [logger ThreadHandler](INFO): Thread cancelled.
2021-11-17T18:40:23.404Z,1637174423.404 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2021-11-17T18:40:23.404Z,1637174423.404 [CommandLine ThreadHandler](INFO): Thread cancelled.
2021-11-17T18:40:23.405Z,1637174423.405 [CommandLine](INFO): Join timeout helper Thread ID is 7727
2021-11-17T18:40:23.496Z,1637174423.496 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2021-11-17T18:40:23.496Z,1637174423.496 [CommandLine ThreadHandler](INFO): Thread cancelled.
2021-11-17T18:40:23.516Z,1637174423.516 [ComponentRegistry](INFO): Shutting down CommandExec ThreadHandler
2021-11-17T18:40:23.516Z,1637174423.516 [CommandExec ThreadHandler](INFO): Thread cancelled.
2021-11-17T18:40:23.517Z,1637174423.517 [CommandExec](INFO): Join timeout helper Thread ID is 7728
2021-11-17T18:40:23.528Z,1637174423.528 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2021-11-17T18:40:23.528Z,1637174423.528 [controlThread ThreadHandler](INFO): Thread cancelled.
2021-11-17T18:40:23.529Z,1637174423.529 [controlThread](INFO): Join timeout helper Thread ID is 7729
2021-11-17T18:40:23.676Z,1637174423.676 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2021-11-17T18:40:23.676Z,1637174423.676 [controlThread](DEBUG): Uninitializing ControlThread
2021-11-17T18:40:23.676Z,1637174423.676 [AHRS_M2](INFO): Powering down
2021-11-17T18:40:23.748Z,1637174423.748 [NAL9602](INFO): Powering down
2021-11-17T18:40:23.750Z,1637174423.750 [DAT](INFO): Powering down
2021-11-17T18:40:23.870Z,1637174423.870 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2021-11-17T18:40:23.871Z,1637174423.871 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2021-11-17T18:40:23.871Z,1637174423.871 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2021-11-17T18:40:23.872Z,1637174423.872 [MissionManager](INFO): Uninitializing Mission Default
2021-11-17T18:40:23.872Z,1637174423.872 [Default] Stopped
2021-11-17T18:40:23.872Z,1637174423.872 [Default](DEBUG): Aggregate::uninitialize Default
2021-11-17T18:40:23.872Z,1637174423.872 [Default:B.GoToSurface] Stopped
2021-11-17T18:40:23.872Z,1637174423.872 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2021-11-17T18:40:23.872Z,1637174423.872 [Default:CheckIn] Stopped
2021-11-17T18:40:23.872Z,1637174423.872 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-11-17T18:40:23.872Z,1637174423.872 [Default:CheckIn:Read_GPS] Stopped
2021-11-17T18:40:23.876Z,1637174423.876 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2021-11-17T18:40:23.877Z,1637174423.877 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2021-11-17T18:40:23.877Z,1637174423.877 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2021-11-17T18:40:23.877Z,1637174423.877 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2021-11-17T18:40:23.878Z,1637174423.878 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2021-11-17T18:40:23.878Z,1637174423.878 [BuoyancyServo](INFO): Powering down
2021-11-17T18:40:23.892Z,1637174423.892 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2021-11-17T18:40:23.892Z,1637174423.892 [ElevatorServo](INFO): Powering down
2021-11-17T18:40:23.893Z,1637174423.893 [MassServo](DEBUG): Uninitialize Mass Servo.
2021-11-17T18:40:23.893Z,1637174423.893 [MassServo](INFO): Powering down
2021-11-17T18:40:23.894Z,1637174423.894 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2021-11-17T18:40:23.894Z,1637174423.894 [RudderServo](INFO): Powering down
2021-11-17T18:40:23.895Z,1637174423.895 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2021-11-17T18:40:23.895Z,1637174423.895 [ThrusterServo](INFO): Powering down
2021-11-17T18:40:23.896Z,1637174423.896 [SBIT](DEBUG): Uninitialize SBIT Component.
2021-11-17T18:40:23.896Z,1637174423.896 [IBIT](DEBUG): Uninitialize IBIT Component.
2021-11-17T18:40:23.896Z,1637174423.896 [CBIT](DEBUG): Uninitialize CBIT Component.
2021-11-17T18:40:23.896Z,1637174423.896 [CBIT](DEBUG): Powering off loads.
2021-11-17T18:40:23.908Z,1637174423.908 [CBIT](DEBUG): Disabling WDT.
2021-11-17T18:40:23.920Z,1637174423.920 [CBIT](DEBUG): Opening all GF detection circuits.
2021-11-17T18:40:23.921Z,1637174423.921 [controlThread ThreadHandler](INFO): Thread cancelled.
2021-11-17T18:40:23.991Z,1637174423.991 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2021-11-17T18:40:24.006Z,1637174424.006 [Onboard ThreadHandler](INFO): Thread cancelled.
2021-11-17T18:40:24.012Z,1637174424.012 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2021-11-17T18:40:24.124Z,1637174424.124 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2021-11-17T18:40:24.128Z,1637174424.128 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2021-11-17T18:40:24.168Z,1637174424.168 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2021-11-17T18:40:24.231Z,1637174424.231 [logger ThreadHandler](INFO): Thread cancelled.