2021-11-17T17:52:09.528Z,1637171529.528 [Supervisor](DEBUG): Initializing supervisor.
2021-11-17T17:52:09.533Z,1637171529.533 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2021-11-17T17:52:09.533Z,1637171529.533 [SyncHandler](INFO): Protected caller Thread ID is 7355
2021-11-17T17:52:09.534Z,1637171529.534 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2021-11-17T17:52:09.535Z,1637171529.535 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2021-11-17T17:52:09.536Z,1637171529.536 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 7356
2021-11-17T17:52:09.540Z,1637171529.540 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2021-11-17T17:52:09.559Z,1637171529.559 [ComponentRegistry](DEBUG): Component "CommandExec" handled in its own thread.
2021-11-17T17:52:09.560Z,1637171529.560 [CommandExec ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2021-11-17T17:52:09.560Z,1637171529.560 [CommandExec ThreadHandler](INFO): Protected caller Thread ID is 7357
2021-11-17T17:52:09.564Z,1637171529.564 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2021-11-17T17:52:09.565Z,1637171529.565 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2021-11-17T17:52:09.566Z,1637171529.566 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 7358
2021-11-17T17:52:09.568Z,1637171529.568 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2021-11-17T17:52:09.569Z,1637171529.569 [logger ThreadHandler](DEBUG): Created PCaller Thread at 405114E0
2021-11-17T17:52:09.569Z,1637171529.569 [logger ThreadHandler](INFO): Protected caller Thread ID is 7359
2021-11-17T17:52:09.573Z,1637171529.573 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2021-11-17T17:52:09.574Z,1637171529.574 [Supervisor](INFO): Looking for Config files in directory: Config/
2021-11-17T17:52:09.578Z,1637171529.578 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2021-11-17T17:52:09.831Z,1637171529.831 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2021-11-17T17:52:09.831Z,1637171529.831 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2021-11-17T17:52:09.914Z,1637171529.914 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2021-11-17T17:52:10.439Z,1637171530.439 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2021-11-17T17:52:10.441Z,1637171530.441 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2021-11-17T17:52:10.775Z,1637171530.775 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2021-11-17T17:52:10.776Z,1637171530.776 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2021-11-17T17:52:10.873Z,1637171530.873 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2021-11-17T17:52:10.873Z,1637171530.873 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2021-11-17T17:52:11.247Z,1637171531.247 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2021-11-17T17:52:11.249Z,1637171531.249 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2021-11-17T17:52:11.449Z,1637171531.449 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2021-11-17T17:52:11.451Z,1637171531.451 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2021-11-17T17:52:11.923Z,1637171531.923 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2021-11-17T17:52:11.923Z,1637171531.923 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2021-11-17T17:52:12.052Z,1637171532.052 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2021-11-17T17:52:12.053Z,1637171532.053 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2021-11-17T17:52:12.133Z,1637171532.133 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2021-11-17T17:52:12.821Z,1637171532.821 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2021-11-17T17:52:12.821Z,1637171532.821 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2021-11-17T17:52:13.191Z,1637171533.191 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2021-11-17T17:52:13.192Z,1637171533.192 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2021-11-17T17:52:13.393Z,1637171533.393 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2021-11-17T17:52:14.222Z,1637171534.222 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2021-11-17T17:52:14.478Z,1637171534.478 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2021-11-17T17:52:14.478Z,1637171534.478 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2021-11-17T17:52:14.633Z,1637171534.633 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2021-11-17T17:52:14.635Z,1637171534.635 [Supervisor](INFO): Opening Config file at: Config/Dock.cfg
2021-11-17T17:52:14.865Z,1637171534.865 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Dock
2021-11-17T17:52:14.867Z,1637171534.867 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2021-11-17T17:52:14.869Z,1637171534.869 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg
2021-11-17T17:52:14.961Z,1637171534.961 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2021-11-17T17:52:15.048Z,1637171535.048 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2021-11-17T17:52:15.150Z,1637171535.150 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg
2021-11-17T17:52:15.233Z,1637171535.233 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2021-11-17T17:52:15.330Z,1637171535.330 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2021-11-17T17:52:15.433Z,1637171535.433 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2021-11-17T17:52:15.620Z,1637171535.620 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg
2021-11-17T17:52:15.696Z,1637171535.696 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2021-11-17T17:52:15.845Z,1637171535.845 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2021-11-17T17:52:15.984Z,1637171535.984 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2021-11-17T17:52:16.100Z,1637171536.100 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Battery.cfg
2021-11-17T17:52:16.367Z,1637171536.367 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2021-11-17T17:52:16.369Z,1637171536.369 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/root/
2021-11-17T17:52:16.369Z,1637171536.369 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2021-11-17T17:52:16.384Z,1637171536.384 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2021-11-17T17:52:16.456Z,1637171536.456 [VerticalControl](DEBUG): Construct VerticalControl.
2021-11-17T17:52:16.518Z,1637171536.518 [VerticalControl] Loaded
2021-11-17T17:52:16.518Z,1637171536.518 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2021-11-17T17:52:16.521Z,1637171536.521 [HorizontalControl](DEBUG): Construct HorizontalControl.
2021-11-17T17:52:16.559Z,1637171536.559 [HorizontalControl] Loaded
2021-11-17T17:52:16.559Z,1637171536.559 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2021-11-17T17:52:16.562Z,1637171536.562 [SpeedControl](DEBUG): Construct SpeedControl.
2021-11-17T17:52:16.565Z,1637171536.565 [SpeedControl] Loaded
2021-11-17T17:52:16.565Z,1637171536.565 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2021-11-17T17:52:16.568Z,1637171536.568 [LoopControl](DEBUG): Construct LoopControl.
2021-11-17T17:52:16.568Z,1637171536.568 [LoopControl] Loaded
2021-11-17T17:52:16.568Z,1637171536.568 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2021-11-17T17:52:16.569Z,1637171536.569 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2021-11-17T17:52:16.569Z,1637171536.569 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2021-11-17T17:52:16.585Z,1637171536.585 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2021-11-17T17:52:16.585Z,1637171536.585 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2021-11-17T17:52:16.717Z,1637171536.717 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2021-11-17T17:52:16.718Z,1637171536.718 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2021-11-17T17:52:16.896Z,1637171536.896 [BuoyancyServo] Loaded
2021-11-17T17:52:16.896Z,1637171536.896 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2021-11-17T17:52:16.916Z,1637171536.916 [ElevatorServo] Loaded
2021-11-17T17:52:16.916Z,1637171536.916 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2021-11-17T17:52:16.934Z,1637171536.934 [MassServo] Loaded
2021-11-17T17:52:16.935Z,1637171536.935 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2021-11-17T17:52:16.953Z,1637171536.953 [RudderServo] Loaded
2021-11-17T17:52:16.953Z,1637171536.953 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2021-11-17T17:52:16.971Z,1637171536.971 [ThrusterServo] Loaded
2021-11-17T17:52:16.971Z,1637171536.971 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2021-11-17T17:52:16.972Z,1637171536.972 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2021-11-17T17:52:16.972Z,1637171536.972 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2021-11-17T17:52:17.068Z,1637171537.068 [DeadReckonUsingMultipleVelocitySources] Loaded
2021-11-17T17:52:17.068Z,1637171537.068 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2021-11-17T17:52:17.081Z,1637171537.081 [NavChart] Loaded
2021-11-17T17:52:17.082Z,1637171537.082 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2021-11-17T17:52:17.087Z,1637171537.087 [UniversalFixResidualReporter] Loaded
2021-11-17T17:52:17.088Z,1637171537.088 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2021-11-17T17:52:17.088Z,1637171537.088 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2021-11-17T17:52:17.089Z,1637171537.089 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2021-11-17T17:52:17.171Z,1637171537.171 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2021-11-17T17:52:17.171Z,1637171537.171 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2021-11-17T17:52:17.685Z,1637171537.685 [AHRS_M2] Loaded
2021-11-17T17:52:17.685Z,1637171537.685 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2021-11-17T17:52:18.508Z,1637171538.508 [BPC1] Loaded
2021-11-17T17:52:18.509Z,1637171538.509 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2021-11-17T17:52:18.529Z,1637171538.529 [Depth_Keller] Loaded
2021-11-17T17:52:18.529Z,1637171538.529 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2021-11-17T17:52:18.534Z,1637171538.534 [DropWeight] Loaded
2021-11-17T17:52:18.534Z,1637171538.534 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2021-11-17T17:52:18.595Z,1637171538.595 [NAL9602] Loaded
2021-11-17T17:52:18.595Z,1637171538.595 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2021-11-17T17:52:18.625Z,1637171538.625 [Onboard] Loaded
2021-11-17T17:52:18.626Z,1637171538.626 [ComponentRegistry](DEBUG): Component "Onboard" handled in its own thread.
2021-11-17T17:52:18.627Z,1637171538.627 [Onboard ThreadHandler](DEBUG): Created PCaller Thread at 408C64E0
2021-11-17T17:52:18.627Z,1637171538.627 [Onboard ThreadHandler](INFO): Protected caller Thread ID is 7444
2021-11-17T17:52:18.640Z,1637171538.640 [Power24vConverter] Loaded
2021-11-17T17:52:18.641Z,1637171538.641 [ComponentRegistry](DEBUG): SyncComponent "Power24vConverter" handled in the control thread.
2021-11-17T17:52:18.655Z,1637171538.655 [Radio_Surface] Loaded
2021-11-17T17:52:18.656Z,1637171538.656 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2021-11-17T17:52:18.657Z,1637171538.657 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 408F64E0
2021-11-17T17:52:18.657Z,1637171538.657 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 7445
2021-11-17T17:52:18.740Z,1637171538.740 [DAT] Loaded
2021-11-17T17:52:18.740Z,1637171538.740 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread.
2021-11-17T17:52:18.740Z,1637171538.740 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2021-11-17T17:52:18.741Z,1637171538.741 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2021-11-17T17:52:19.353Z,1637171539.353 [DepthRateCalculator] Loaded
2021-11-17T17:52:19.353Z,1637171539.353 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2021-11-17T17:52:19.358Z,1637171539.358 [PitchRateCalculator] Loaded
2021-11-17T17:52:19.358Z,1637171539.358 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2021-11-17T17:52:19.367Z,1637171539.367 [SpeedCalculator] Loaded
2021-11-17T17:52:19.368Z,1637171539.368 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2021-11-17T17:52:19.381Z,1637171539.381 [TempGradientCalculator] Loaded
2021-11-17T17:52:19.382Z,1637171539.382 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2021-11-17T17:52:19.386Z,1637171539.386 [YawRateCalculator] Loaded
2021-11-17T17:52:19.386Z,1637171539.386 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2021-11-17T17:52:19.404Z,1637171539.404 [ElevatorOffsetCalculator] Loaded
2021-11-17T17:52:19.405Z,1637171539.405 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2021-11-17T17:52:19.405Z,1637171539.405 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2021-11-17T17:52:19.406Z,1637171539.406 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2021-11-17T17:52:19.737Z,1637171539.737 [CANONSampler] Loaded
2021-11-17T17:52:19.737Z,1637171539.737 [ComponentRegistry](DEBUG): SyncComponent "CANONSampler" handled in the control thread.
2021-11-17T17:52:19.797Z,1637171539.797 [CTD_Seabird] Loaded
2021-11-17T17:52:19.797Z,1637171539.797 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread.
2021-11-17T17:52:19.798Z,1637171539.798 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 409AB4E0
2021-11-17T17:52:19.799Z,1637171539.799 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 7446
2021-11-17T17:52:19.819Z,1637171539.819 [PAR_Licor] Loaded
2021-11-17T17:52:19.819Z,1637171539.819 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2021-11-17T17:52:19.852Z,1637171539.852 [WetLabsBB2FL] Loaded
2021-11-17T17:52:19.852Z,1637171539.852 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2021-11-17T17:52:19.853Z,1637171539.853 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 409DB4E0
2021-11-17T17:52:19.854Z,1637171539.854 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 7447
2021-11-17T17:52:19.855Z,1637171539.855 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2021-11-17T17:52:19.855Z,1637171539.855 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2021-11-17T17:52:19.896Z,1637171539.896 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2021-11-17T17:52:19.896Z,1637171539.896 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2021-11-17T17:52:20.266Z,1637171540.266 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2021-11-17T17:52:20.266Z,1637171540.266 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2021-11-17T17:52:20.439Z,1637171540.439 [SBIT](DEBUG): Construct Startup Built In Test.
2021-11-17T17:52:20.449Z,1637171540.449 [SBIT] Loaded
2021-11-17T17:52:20.449Z,1637171540.449 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2021-11-17T17:52:20.452Z,1637171540.452 [IBIT](DEBUG): Construct Initiated Built In Test.
2021-11-17T17:52:20.465Z,1637171540.465 [IBIT] Loaded
2021-11-17T17:52:20.465Z,1637171540.465 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2021-11-17T17:52:20.471Z,1637171540.471 [CBIT](DEBUG): Construct Continuous Built In Test.
2021-11-17T17:52:20.574Z,1637171540.574 [CBIT] Loaded
2021-11-17T17:52:20.574Z,1637171540.574 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2021-11-17T17:52:20.575Z,1637171540.575 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2021-11-17T17:52:20.575Z,1637171540.575 [Module Loader](DEBUG): Loading Module at Modules/Dock.so
2021-11-17T17:52:20.689Z,1637171540.689 [Module Loader](DEBUG): Loaded Module: Dock (Contains behaviors and commands for docking)
2021-11-17T17:52:20.695Z,1637171540.695 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2021-11-17T17:52:20.698Z,1637171540.698 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2021-11-17T17:52:20.709Z,1637171540.709 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2021-11-17T17:52:20.710Z,1637171540.710 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40B104E0
2021-11-17T17:52:20.710Z,1637171540.710 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 7448
2021-11-17T17:52:20.715Z,1637171540.715 [Supervisor](INFO): Main Thread ID is 6245
2021-11-17T17:52:20.715Z,1637171540.715 [Supervisor](DEBUG): Running supervisor.
2021-11-17T17:52:20.716Z,1637171540.716 [CommandExec ThreadHandler](INFO): Handler Thread ID is 7449
2021-11-17T17:52:20.716Z,1637171540.716 [CommandExec](INFO): Initializing the command executive.
2021-11-17T17:52:20.718Z,1637171540.718 [CommandLine ThreadHandler](INFO): Handler Thread ID is 7450
2021-11-17T17:52:20.720Z,1637171540.720 [controlThread ThreadHandler](INFO): Handler Thread ID is 7451
2021-11-17T17:52:20.720Z,1637171540.720 [controlThread](DEBUG): Initializing ControlThread
2021-11-17T17:52:20.721Z,1637171540.721 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2021-11-17T17:52:20.723Z,1637171540.723 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2021-11-17T17:52:20.724Z,1637171540.724 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2021-11-17T17:52:20.725Z,1637171540.725 [LoopControl](DEBUG): Initialize LoopControlComponent.
2021-11-17T17:52:20.726Z,1637171540.726 [NavChart](DEBUG): Initialize NavChart Navigation.
2021-11-17T17:52:20.727Z,1637171540.727 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2021-11-17T17:52:20.733Z,1637171540.733 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2021-11-17T17:52:20.734Z,1637171540.734 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2021-11-17T17:52:20.734Z,1637171540.734 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2021-11-17T17:52:20.734Z,1637171540.734 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2021-11-17T17:52:20.735Z,1637171540.735 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2021-11-17T17:52:20.735Z,1637171540.735 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2021-11-17T17:52:20.740Z,1637171540.740 [SBIT](INFO): Initialize SBIT Component.
2021-11-17T17:52:20.740Z,1637171540.740 [SBIT](IMPORTANT): git: 2021-10-11a
2021-11-17T17:52:20.740Z,1637171540.740 [SBIT](INFO): git hash: 36f3a97de7a122c995f034a375e3cefac6406048
2021-11-17T17:52:20.741Z,1637171540.741 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2021-11-17T17:52:20.742Z,1637171540.742 [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-17T17:52:20.743Z,1637171540.743 [SBIT](INFO): Beginning SBIT in 84.000000 seconds.
2021-11-17T17:52:20.744Z,1637171540.744 [IBIT](INFO): Initialize IBIT Component.
2021-11-17T17:52:20.745Z,1637171540.745 [CBIT](DEBUG): Initialize CBIT Component.
2021-11-17T17:52:20.746Z,1637171540.746 [logger ThreadHandler](INFO): Handler Thread ID is 7452
2021-11-17T17:52:20.755Z,1637171540.755 [CBIT](DEBUG): Initialized mux pins.
2021-11-17T17:52:20.756Z,1637171540.756 [CBIT](DEBUG): Initializing the watchdog timer.
2021-11-17T17:52:20.764Z,1637171540.764 [Onboard ThreadHandler](INFO): Handler Thread ID is 7453
2021-11-17T17:52:20.785Z,1637171540.785 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2021-11-17T17:52:20.785Z,1637171540.785 [CBIT](DEBUG): Initializing heartbeat.
2021-11-17T17:52:20.785Z,1637171540.785 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 7454
2021-11-17T17:52:20.800Z,1637171540.800 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 7455
2021-11-17T17:52:20.800Z,1637171540.800 [CTD_Seabird](DEBUG): Initializing CTD_Seabird.
2021-11-17T17:52:20.805Z,1637171540.805 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 7457
2021-11-17T17:52:20.808Z,1637171540.808 [WetLabsBB2FL](INFO): Powering up
2021-11-17T17:52:20.809Z,1637171540.809 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 7459
2021-11-17T17:52:20.814Z,1637171540.814 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2021-11-17T17:52:20.814Z,1637171540.814 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2021-11-17T17:52:20.814Z,1637171540.814 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2021-11-17T17:52:20.815Z,1637171540.815 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2021-11-17T17:52:20.815Z,1637171540.815 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2021-11-17T17:52:20.815Z,1637171540.815 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2021-11-17T17:52:20.816Z,1637171540.816 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2021-11-17T17:52:20.816Z,1637171540.816 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2021-11-17T17:52:20.816Z,1637171540.816 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2021-11-17T17:52:20.816Z,1637171540.816 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2021-11-17T17:52:20.817Z,1637171540.817 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2021-11-17T17:52:20.817Z,1637171540.817 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2021-11-17T17:52:20.817Z,1637171540.817 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2021-11-17T17:52:20.817Z,1637171540.817 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2021-11-17T17:52:20.817Z,1637171540.817 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2021-11-17T17:52:20.818Z,1637171540.818 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2021-11-17T17:52:20.855Z,1637171540.855 [CBIT](DEBUG): Deactivating GF circuits.
2021-11-17T17:52:20.855Z,1637171540.855 [CBIT](DEBUG): Deactivating emergency mode.
2021-11-17T17:52:20.892Z,1637171540.892 [CBIT](DEBUG): Backplane powered.
2021-11-17T17:52:20.893Z,1637171540.893 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2021-11-17T17:52:20.931Z,1637171540.931 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2021-11-17T17:52:20.959Z,1637171540.959 [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-17T17:52:20.960Z,1637171540.960 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2021-11-17T17:52:21.039Z,1637171541.039 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2021-11-17T17:52:21.048Z,1637171541.048 [Default:A.Wait](DEBUG): Construct Wait.
2021-11-17T17:52:21.051Z,1637171541.051 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2021-11-17T17:52:21.100Z,1637171541.100 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2021-11-17T17:52:21.105Z,1637171541.105 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2021-11-17T17:52:21.128Z,1637171541.128 [Default:E.Execute](DEBUG): Construct Execute.
2021-11-17T17:52:21.148Z,1637171541.148 [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-17T17:52:21.152Z,1637171541.152 [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-17T17:52:21.164Z,1637171541.164 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2021-11-17T17:52:21.191Z,1637171541.191 [Radio_Surface](INFO): Powering up
2021-11-17T17:52:21.242Z,1637171541.242 [Power24vConverter](INFO): Powering up.
2021-11-17T17:52:21.243Z,1637171541.243 [DAT](INFO): Powering up
2021-11-17T17:52:21.243Z,1637171541.243 [DAT](DEBUG): Initializing DAT.
2021-11-17T17:52:21.260Z,1637171541.260 [CANONSampler](INFO): Powering down
2021-11-17T17:52:21.333Z,1637171541.333 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2021-11-17T17:52:21.348Z,1637171541.348 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2021-11-17T17:52:21.349Z,1637171541.349 [ElevatorServo](DEBUG): Initializing EZServoServo.
2021-11-17T17:52:21.356Z,1637171541.356 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2021-11-17T17:52:21.357Z,1637171541.357 [MassServo](DEBUG): Initializing EZServoServo.
2021-11-17T17:52:21.364Z,1637171541.364 [MassServo](DEBUG): Initializing MassServo.
2021-11-17T17:52:21.365Z,1637171541.365 [RudderServo](DEBUG): Initializing EZServoServo.
2021-11-17T17:52:21.372Z,1637171541.372 [RudderServo](DEBUG): Initializing RudderServo.
2021-11-17T17:52:21.373Z,1637171541.373 [ThrusterServo](DEBUG): Initializing EZServoServo.
2021-11-17T17:52:21.380Z,1637171541.380 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2021-11-17T17:52:21.585Z,1637171541.585 [DropWeight](CRITICAL): DROP WEIGHT MISSING.

2021-11-17T17:52:21.585Z,1637171541.585 [DropWeight] Hardware Fault, FailCount= 1
2021-11-17T17:52:21.585Z,1637171541.585 [DropWeight](ERROR): Hardware Fault
2021-11-17T17:52:21.620Z,1637171541.620 [CommandExec](FAULT): Scheduling is paused
2021-11-17T17:52:21.620Z,1637171541.620 [CBIT](INFO): Critical error at 20211117T175221
2021-11-17T17:52:21.620Z,1637171541.620 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals
2021-11-17T17:52:21.623Z,1637171541.623 [CBIT](ERROR): Hardware Fault in component: DropWeight
2021-11-17T17:52:21.624Z,1637171541.624 [CBIT](CRITICAL): Hardware Fault in component: DropWeight
2021-11-17T17:52:22.303Z,1637171542.303 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2021-11-17T17:52:22.304Z,1637171542.304 [RudderServo](FAULT): Rudder failed to initialize
2021-11-17T17:52:22.304Z,1637171542.304 [RudderServo] Communications Fault, FailCount= 1
2021-11-17T17:52:22.304Z,1637171542.304 [RudderServo](ERROR): Communications Fault
2021-11-17T17:52:22.402Z,1637171542.402 [CBIT](INFO): Critical error at 20211117T175221
2021-11-17T17:52:22.404Z,1637171542.404 [CBIT](ERROR): Communications Fault in component: RudderServo
2021-11-17T17:52:22.629Z,1637171542.629 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2021-11-17T17:52:22.629Z,1637171542.629 [RudderServo](INFO): Powering down
2021-11-17T17:52:22.916Z,1637171542.916 [WetLabsBB2FL](INFO): Powering down
2021-11-17T17:52:23.241Z,1637171543.241 [RudderServo](DEBUG): Initializing EZServoServo.
2021-11-17T17:52:23.360Z,1637171543.360 [RudderServo](DEBUG): Initializing RudderServo.
2021-11-17T17:52:23.365Z,1637171543.365 [CBIT](INFO): Clearing failed state for component RudderServo
2021-11-17T17:52:23.365Z,1637171543.365 [RudderServo] No Fault, FailCount= 1
2021-11-17T17:52:32.925Z,1637171552.925 [DAT](INFO): DAT read: 

2021-11-17T17:52:32.927Z,1637171552.927 [DAT](INFO): DAT read: Teledyne Benthos DAT-900 Series

2021-11-17T17:52:34.538Z,1637171554.538 [DAT](INFO): DAT read: MF Frequency Band

2021-11-17T17:52:34.539Z,1637171554.539 [DAT](INFO): DAT read: Directional Acoustic Transponder version 8.14.2

2021-11-17T17:52:34.540Z,1637171554.540 [DAT](INFO): DAT read: Nov 17 2021 17:51:54 

2021-11-17T17:52:35.750Z,1637171555.750 [DAT](INFO): DAT read: Features enabled [Bearing]

2021-11-17T17:52:35.751Z,1637171555.751 [DAT](INFO): DAT read: CONNECT 00800 bits/sec 1 of 4, Rate 1/2 CC 12.50ms MGP

2021-11-17T17:52:35.752Z,1637171555.752 [DAT](INFO): commRate: 800
2021-11-17T17:52:37.769Z,1637171557.769 [DAT](INFO): entering command mode
2021-11-17T17:52:38.173Z,1637171558.173 [DAT](INFO): DAT read: 

2021-11-17T17:52:38.174Z,1637171558.174 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T17:52:38.577Z,1637171558.577 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T17:52:38.981Z,1637171558.981 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T17:52:39.385Z,1637171559.385 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T17:52:39.789Z,1637171559.789 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T17:52:40.193Z,1637171560.193 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T17:52:40.597Z,1637171560.597 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T17:52:41.001Z,1637171561.001 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T17:52:41.405Z,1637171561.405 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T17:52:41.816Z,1637171561.816 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T17:52:42.213Z,1637171562.213 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T17:52:42.617Z,1637171562.617 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T17:52:43.021Z,1637171563.021 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T17:52:43.425Z,1637171563.425 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T17:52:43.828Z,1637171563.828 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T17:52:44.233Z,1637171564.233 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T17:52:44.637Z,1637171564.637 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T17:52:45.049Z,1637171565.049 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T17:52:45.445Z,1637171565.445 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T17:52:45.849Z,1637171565.849 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T17:52:46.253Z,1637171566.253 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T17:52:46.659Z,1637171566.659 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T17:52:47.061Z,1637171567.061 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T17:52:47.465Z,1637171567.465 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T17:52:47.869Z,1637171567.869 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T17:52:48.273Z,1637171568.273 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T17:52:48.677Z,1637171568.677 [NAL9602](INFO): Powering up NAL9602
2021-11-17T17:52:48.679Z,1637171568.679 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T17:52:49.081Z,1637171569.081 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T17:52:49.485Z,1637171569.485 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T17:52:49.889Z,1637171569.889 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T17:52:50.299Z,1637171570.299 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T17:52:50.697Z,1637171570.697 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T17:52:51.101Z,1637171571.101 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T17:52:51.505Z,1637171571.505 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T17:52:51.913Z,1637171571.913 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T17:52:52.314Z,1637171572.314 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T17:52:52.717Z,1637171572.717 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T17:52:53.121Z,1637171573.121 [DAT](DEBUG): checking for command mode acknowledgment
2021-11-17T17:52:53.121Z,1637171573.121 [DAT](FAULT): failed to enter command mode
2021-11-17T17:52:53.529Z,1637171573.529 [DAT](INFO): entering command mode
2021-11-17T17:52:53.930Z,1637171573.930 [DAT](INFO): DAT read: user:1>

2021-11-17T17:52:53.931Z,1637171573.931 [DAT](INFO): DAT read: Command '+++' not found

2021-11-17T17:52:53.931Z,1637171573.931 [DAT](INFO): DAT read: Error

2021-11-17T17:52:53.931Z,1637171573.931 [DAT](INFO): setting verbose to 3
2021-11-17T17:52:54.333Z,1637171574.333 [DAT](INFO): DAT read: user:2>

2021-11-17T17:52:54.334Z,1637171574.334 [DAT](INFO): DAT read: Verbose         | 3           

2021-11-17T17:52:54.335Z,1637171574.335 [DAT](INFO): set verbose to 3
2021-11-17T17:52:54.335Z,1637171574.335 [DAT](INFO): setting DatVerbose to 27440
2021-11-17T17:52:54.737Z,1637171574.737 [DAT](INFO): DAT read: user:3>

2021-11-17T17:52:54.738Z,1637171574.738 [DAT](INFO): DAT read: DatVerbose      | 27440       

2021-11-17T17:52:54.739Z,1637171574.739 [DAT](INFO): set DatVerbose to 27440
2021-11-17T17:52:54.739Z,1637171574.739 [DAT](INFO): setting transmit power to 8
2021-11-17T17:52:55.141Z,1637171575.141 [DAT](INFO): DAT read: user:4>

2021-11-17T17:52:55.142Z,1637171575.142 [DAT](INFO): DAT read: TxPower         | 8 (Max)     

2021-11-17T17:52:55.143Z,1637171575.143 [DAT](INFO): set transmit power to 8
2021-11-17T17:52:55.143Z,1637171575.143 [DAT](INFO): setting local address to 7
2021-11-17T17:52:55.545Z,1637171575.545 [DAT](INFO): DAT read: user:5>

2021-11-17T17:52:55.546Z,1637171575.546 [DAT](INFO): DAT read: LocalAddr       | 7           

2021-11-17T17:52:55.547Z,1637171575.547 [DAT](INFO): set local address to 7
2021-11-17T17:52:59.585Z,1637171579.585 [NAL9602](INFO): NAL9602 initialized
2021-11-17T17:53:02.153Z,1637171582.153 [CommandExec](IMPORTANT): got command strobe off
2021-11-17T17:53:02.153Z,1637171582.153 [CommandExec](IMPORTANT): Deactivating strobe
2021-11-17T17:53:10.742Z,1637171590.742 [CommandExec](IMPORTANT): got command maintain sensor NAL9602.latitude_fix 36.799999 degree
2021-11-17T17:53:10.750Z,1637171590.750 [ComponentRegistry](DEBUG): SyncComponent "Maintain_NAL9602.latitude_fix" handled in the control thread.
2021-11-17T17:53:10.751Z,1637171590.751 [CommandExec](IMPORTANT): got command maintain sensor NAL9602.longitude_fix -121.900002 degree
2021-11-17T17:53:10.758Z,1637171590.758 [ComponentRegistry](DEBUG): SyncComponent "Maintain_NAL9602.longitude_fix" handled in the control thread.
2021-11-17T17:53:10.959Z,1637171590.959 [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-17T17:53:11.315Z,1637171591.315 [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-17T17:53:11.315Z,1637171591.315 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2021-11-17T17:53:11.315Z,1637171591.315 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-11-17T17:53:11.374Z,1637171591.374 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-11-17T17:53:11.763Z,1637171591.763 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-11-17T17:53:11.763Z,1637171591.763 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2021-11-17T17:53:12.538Z,1637171592.538 [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-17T17:53:12.539Z,1637171592.539 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2
2021-11-17T17:53:12.539Z,1637171592.539 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-11-17T17:53:12.559Z,1637171592.559 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-11-17T17:53:12.978Z,1637171592.978 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-11-17T17:53:12.978Z,1637171592.978 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2
2021-11-17T17:53:13.800Z,1637171593.800 [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-17T17:53:13.800Z,1637171593.800 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 3
2021-11-17T17:53:13.800Z,1637171593.800 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-11-17T17:53:13.870Z,1637171593.870 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-11-17T17:53:14.229Z,1637171594.229 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-11-17T17:53:14.229Z,1637171594.229 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 3
2021-11-17T17:53:14.957Z,1637171594.957 [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-17T17:53:14.957Z,1637171594.957 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 4
2021-11-17T17:53:14.957Z,1637171594.957 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-11-17T17:53:15.036Z,1637171595.036 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-11-17T17:53:15.398Z,1637171595.398 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-11-17T17:53:15.398Z,1637171595.398 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 4
2021-11-17T17:53:16.185Z,1637171596.185 [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-17T17:53:16.186Z,1637171596.186 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 5
2021-11-17T17:53:16.186Z,1637171596.186 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-11-17T17:53:16.253Z,1637171596.253 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-11-17T17:53:16.577Z,1637171596.577 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-11-17T17:53:16.577Z,1637171596.577 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 5
2021-11-17T17:53:17.374Z,1637171597.374 [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-17T17:53:17.374Z,1637171597.374 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 6
2021-11-17T17:53:17.374Z,1637171597.374 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-11-17T17:53:17.427Z,1637171597.427 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-11-17T17:53:17.803Z,1637171597.803 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-11-17T17:53:17.803Z,1637171597.803 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 6
2021-11-17T17:53:18.613Z,1637171598.613 [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-17T17:53:18.613Z,1637171598.613 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 7
2021-11-17T17:53:18.613Z,1637171598.613 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-11-17T17:53:18.680Z,1637171598.680 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-11-17T17:53:19.047Z,1637171599.047 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-11-17T17:53:19.047Z,1637171599.047 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 7
2021-11-17T17:53:19.814Z,1637171599.814 [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-17T17:53:19.814Z,1637171599.814 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 8
2021-11-17T17:53:19.814Z,1637171599.814 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-11-17T17:53:19.824Z,1637171599.824 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-11-17T17:53:20.225Z,1637171600.225 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-11-17T17:53:20.225Z,1637171600.225 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 8
2021-11-17T17:53:21.006Z,1637171601.006 [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-17T17:53:21.006Z,1637171601.006 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 9
2021-11-17T17:53:21.006Z,1637171601.006 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-11-17T17:53:21.017Z,1637171601.017 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-11-17T17:53:21.427Z,1637171601.427 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-11-17T17:53:21.428Z,1637171601.428 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 9
2021-11-17T17:53:22.264Z,1637171602.264 [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-17T17:53:22.264Z,1637171602.264 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 10
2021-11-17T17:53:22.264Z,1637171602.264 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-11-17T17:53:22.274Z,1637171602.274 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-11-17T17:53:22.649Z,1637171602.649 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-11-17T17:53:22.649Z,1637171602.649 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 10
2021-11-17T17:53:23.482Z,1637171603.482 [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-17T17:53:23.482Z,1637171603.482 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 11
2021-11-17T17:53:23.482Z,1637171603.482 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-11-17T17:53:23.492Z,1637171603.492 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-11-17T17:53:23.874Z,1637171603.874 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-11-17T17:53:23.874Z,1637171603.874 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 11
2021-11-17T17:53:24.662Z,1637171604.662 [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-17T17:53:24.662Z,1637171604.662 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 12
2021-11-17T17:53:24.662Z,1637171604.662 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-11-17T17:53:24.715Z,1637171604.715 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-11-17T17:53:25.101Z,1637171605.101 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-11-17T17:53:25.101Z,1637171605.101 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 12
2021-11-17T17:53:25.264Z,1637171605.264 [CommandExec](IMPORTANT): got command set NAL9602.time_fix 1637171584.000000 second
2021-11-17T17:53:30.666Z,1637171610.666 [CommandExec](IMPORTANT): got command get depth
2021-11-17T17:53:30.666Z,1637171610.666 [CommandExec](IMPORTANT): depth 0.100564 m
2021-11-17T17:53:38.341Z,1637171618.341 [CommandExec](IMPORTANT): got command show stack
2021-11-17T17:53:38.341Z,1637171618.341 [CommandExec](IMPORTANT): Behavior Stack:

2021-11-17T17:53:38.341Z,1637171618.341 [MissionManager](IMPORTANT): Mission loaded, but not running.
2021-11-17T17:53:45.290Z,1637171625.290 [SBIT](IMPORTANT): Beginning Startup BIT
2021-11-17T17:53:45.333Z,1637171625.333 [CBIT](IMPORTANT): Beginning ground fault scan
2021-11-17T17:53:51.131Z,1637171631.131 [CommandExec](IMPORTANT): got command set NAL9602.time_fix 1637171584.000000 second
2021-11-17T17:53:53.961Z,1637171633.961 [CommandExec](IMPORTANT): got command show stack
2021-11-17T17:53:53.961Z,1637171633.961 [CommandExec](IMPORTANT): Behavior Stack:

2021-11-17T17:53:53.961Z,1637171633.961 [MissionManager](IMPORTANT): Mission loaded, but not running.
2021-11-17T17:53:56.217Z,1637171636.217 [CBIT](ERROR): Ground fault scan returned out of bounds value. Re-running scan.
2021-11-17T17:53:56.582Z,1637171636.582 [CBIT](IMPORTANT): Beginning ground fault scan
2021-11-17T17:54:07.953Z,1637171647.953 [CBIT](ERROR): Ground fault scan returned out of bounds value. Re-running scan.
2021-11-17T17:54:08.413Z,1637171648.413 [CBIT](IMPORTANT): Beginning ground fault scan
2021-11-17T17:54:19.218Z,1637171659.218 [CBIT](ERROR): Ground fault scan returned out of bounds value. Re-running scan.
2021-11-17T17:54:19.218Z,1637171659.218 [CBIT](IMPORTANT): Ground fault scan returned out of bounds value in succession 3 times. Will re-run scan on normal schedule.
2021-11-17T17:54:37.294Z,1637171677.294 [CommandExec](IMPORTANT): got command set NAL9602.time_fix 1637171712.000000 second
2021-11-17T17:54:39.065Z,1637171679.065 [SBIT](IMPORTANT): SBIT PASSED
2021-11-17T17:54:39.065Z,1637171679.065 [SBIT](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2021-11-17T17:54:39.066Z,1637171679.066 [SBIT](IMPORTANT): AMEcho.loadAtStartup=0 bool;

2021-11-17T17:54:39.066Z,1637171679.066 [SBIT](IMPORTANT): BuoyancyServo.fastPumpDepth=6 meter;

2021-11-17T17:54:39.066Z,1637171679.066 [SBIT](IMPORTANT): CANONSampler.loadAtStartup=1 bool;

2021-11-17T17:54:39.066Z,1637171679.066 [SBIT](IMPORTANT): DAT.loadAtStartup=1 bool;

2021-11-17T17:54:39.067Z,1637171679.067 [SBIT](IMPORTANT): DAT.sbdAddress=1 enum;

2021-11-17T17:54:39.067Z,1637171679.067 [SBIT](IMPORTANT): DAT.surfaceThreshold=0 meter;

2021-11-17T17:54:39.067Z,1637171679.067 [SBIT](IMPORTANT): DAT.verbosity=3 count;

2021-11-17T17:54:39.067Z,1637171679.067 [SBIT](IMPORTANT): DataOverHttps.loadAtStartup=0 bool;

2021-11-17T17:54:39.067Z,1637171679.067 [SBIT](IMPORTANT): ESPComponent.loadAtStartup=0 bool;

2021-11-17T17:54:39.067Z,1637171679.067 [SBIT](IMPORTANT): ESPComponent.simulateHardware=1 bool;

2021-11-17T17:54:39.067Z,1637171679.067 [SBIT](IMPORTANT): VerticalControl.buoyancyNeutral=296 cubic_centimeter;

2021-11-17T17:54:39.068Z,1637171679.068 [SBIT](IMPORTANT): VerticalControl.massDefault=-16 millimeter;

2021-11-17T17:54:39.068Z,1637171679.068 [SBIT](IMPORTANT): VerticalControl.surfaceThreshold=2 meter;

2021-11-17T17:54:39.422Z,1637171679.422 [MissionManager](IMPORTANT): Started mission Startup
2021-11-17T17:54:39.422Z,1637171679.422 [Startup] Running Loop=1
2021-11-17T17:54:39.422Z,1637171679.422 [Startup](DEBUG): Aggregate::initialize Startup
2021-11-17T17:54:39.423Z,1637171679.423 [Startup:A.GoToSurface] Running Loop=1
2021-11-17T17:54:39.423Z,1637171679.423 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2021-11-17T17:54:39.424Z,1637171679.424 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2021-11-17T17:54:39.424Z,1637171679.424 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2021-11-17T17:54:39.424Z,1637171679.424 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2021-11-17T17:54:39.425Z,1637171679.425 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2021-11-17T17:54:39.425Z,1637171679.425 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2021-11-17T17:54:39.427Z,1637171679.427 [Startup:StartupSatComms] Running Loop=1
2021-11-17T17:54:39.427Z,1637171679.427 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2021-11-17T17:54:39.427Z,1637171679.427 [Startup:StartupSatComms:A] Running Loop=1
2021-11-17T17:54:39.818Z,1637171679.818 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2021-11-17T17:54:39.818Z,1637171679.818 [Startup:StartupSatComms:A] Stopped
2021-11-17T17:54:39.819Z,1637171679.819 [Startup:StartupSatComms:B] Running Loop=1
2021-11-17T17:54:40.213Z,1637171680.213 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2021-11-17T17:54:41.095Z,1637171681.095 [DAT](INFO): #Outgoing data=1
2021-11-17T17:54:41.096Z,1637171681.096 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-17T17:54:41.229Z,1637171681.229 [DAT](INFO): setting remote address to 1
2021-11-17T17:54:41.653Z,1637171681.653 [DAT](INFO): DAT read: user:6>

2021-11-17T17:54:41.654Z,1637171681.654 [DAT](INFO): DAT read: RemoteAddr      | 1           

2021-11-17T17:54:41.654Z,1637171681.654 [DAT](INFO): set remote address to 1
2021-11-17T17:54:41.655Z,1637171681.655 [DAT](INFO): entering online mode
2021-11-17T17:54:42.057Z,1637171682.057 [DAT](INFO): DAT read: user:7>

2021-11-17T17:54:42.057Z,1637171682.057 [DAT](INFO): DAT read: 

2021-11-17T17:54:42.059Z,1637171682.059 [DAT](INFO): DAT read: CONNECT 00800 bits/sec 1 of 4, Rate 1/2 CC 12.50ms MGP

2021-11-17T17:54:42.059Z,1637171682.059 [DAT](INFO): commRate: 800
2021-11-17T17:54:42.060Z,1637171682.060 [DAT](INFO): online mode acknowledged
2021-11-17T17:54:42.061Z,1637171682.061 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-17T17:54:45.273Z,1637171685.273 [DAT](INFO): DAT read: Forwarding Delay UpTx time:17:54:08.2555

2021-11-17T17:54:45.274Z,1637171685.274 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-17T17:54:52.957Z,1637171692.957 [DAT](INFO): DAT read: Rx Time:17:54:15.0309

2021-11-17T17:54:52.957Z,1637171692.957 [DAT](INFO): received an acoustic signal
2021-11-17T17:54:53.756Z,1637171693.756 [DAT](INFO): DAT read: 17:54:15.0309 LVL= 32752, 32753, 32754, 32755, AGC= 87, IDX= 263, 0.27, 2.870, 2.938, 2.883, 2.905, PHS=-0.039, 0.076,-0.037, RAW= 329.4,   0.0, CAL= 329.8,  -2.3, ROT= 240.2,   2.3

2021-11-17T17:54:53.757Z,1637171693.757 [DAT](INFO): got valid direction response:
 17:54:15.0309 LVL= 32752, 32753, 32754, 32755, AGC= 87, IDX= 263, 0.27, 2.870, 2.938, 2.883, 2.905, PHS=-0.039, 0.076,-0.037, RAW= 329.4,   0.0, CAL= 329.8,  -2.3, ROT= 240.2,   2.3

2021-11-17T17:54:53.757Z,1637171693.757 [DAT](INFO): DAT read: 

2021-11-17T17:54:53.758Z,1637171693.758 [DAT](INFO): DAT read: DATA(0002):~~

2021-11-17T17:54:53.758Z,1637171693.758 [DAT](INFO): Got DATA 2
2021-11-17T17:54:53.759Z,1637171693.759 [DAT](INFO): DAT read: Source:001  Destination:007

2021-11-17T17:54:53.760Z,1637171693.760 [DAT](INFO): Got Src/Dest after DATA 
2021-11-17T17:54:53.760Z,1637171693.760 [DAT](INFO): DATA Src=1, Dst=7
2021-11-17T17:54:53.761Z,1637171693.761 [DAT](INFO): DAT read: CRC:Pass MPD:03.7 PSNR:12.4 AGC:90 SPD:+0.0 CCERR:010

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

2021-11-17T17:54:53.763Z,1637171693.763 [DAT](INFO): DAT read: <EOP>

2021-11-17T17:54:53.800Z,1637171693.800 [DAT](INFO): Sent 39 bytes from file Logs/20211117T174345/Courier0009.lzma.parts
2021-11-17T17:54:53.800Z,1637171693.800 [DAT](INFO): Packets left to send: 0
2021-11-17T17:54:53.803Z,1637171693.803 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-17T17:54:53.807Z,1637171693.807 [DAT](INFO): #Rx 1: Read direction message, but no range.
2021-11-17T17:54:53.809Z,1637171693.809 [DAT](INFO): direction in vehicle frame: [ -0.496574 forward, -0.867066 starboard, 0.040132 keelward ]
2021-11-17T17:54:54.657Z,1637171694.657 [DAT](INFO): #Outgoing data=1
2021-11-17T17:54:54.658Z,1637171694.658 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-17T17:54:54.777Z,1637171694.777 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-17T17:54:58.409Z,1637171698.409 [DAT](INFO): DAT read: Forwarding Delay UpTx time:17:54:21.1053

2021-11-17T17:54:58.409Z,1637171698.409 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-17T17:55:06.879Z,1637171706.879 [DAT](INFO): DAT read: Rx Time:17:54:29.1800

2021-11-17T17:55:06.879Z,1637171706.879 [DAT](INFO): received an acoustic signal
2021-11-17T17:55:08.107Z,1637171708.107 [DAT](INFO): DAT read: 17:54:29.1800 LVL= 32752, 32753, 32754, 32755, AGC= 90, IDX= 178,-0.17, 1.317, 1.366, 1.318, 1.309, PHS= 0.004, 0.101,-0.006, RAW= 334.6, -18.9, CAL= 336.3, -21.4, ROT= 233.7,  21.4

2021-11-17T17:55:08.108Z,1637171708.108 [DAT](INFO): got valid direction response:
 17:54:29.1800 LVL= 32752, 32753, 32754, 32755, AGC= 90, IDX= 178,-0.17, 1.317, 1.366, 1.318, 1.309, PHS= 0.004, 0.101,-0.006, RAW= 334.6, -18.9, CAL= 336.3, -21.4, ROT= 233.7,  21.4

2021-11-17T17:55:08.108Z,1637171708.108 [DAT](INFO): DAT read: 

2021-11-17T17:55:08.109Z,1637171708.109 [DAT](INFO): DAT read: DATA(0002):~~

2021-11-17T17:55:08.109Z,1637171708.109 [DAT](INFO): Got DATA 2
2021-11-17T17:55:08.110Z,1637171708.110 [DAT](INFO): DAT read: Source:001  Destination:007

2021-11-17T17:55:08.110Z,1637171708.110 [DAT](INFO): Got Src/Dest after DATA 
2021-11-17T17:55:08.111Z,1637171708.111 [DAT](INFO): DATA Src=1, Dst=7
2021-11-17T17:55:08.112Z,1637171708.112 [DAT](INFO): DAT read: CRC:Pass MPD:03.8 PSNR:11.4 AGC:91 SPD:+0.1 CCERR:010

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

2021-11-17T17:55:08.114Z,1637171708.114 [DAT](INFO): DAT read: <EOP>

2021-11-17T17:55:08.114Z,1637171708.114 [DAT](INFO): Sent 151 bytes from file Logs/20211117T175124/Courier0000.lzma.parts
2021-11-17T17:55:08.115Z,1637171708.115 [DAT](INFO): Packets left to send: 0
2021-11-17T17:55:08.153Z,1637171708.153 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-17T17:55:08.154Z,1637171708.154 [DAT](INFO): #Rx 2: Read direction message, but no range.
2021-11-17T17:55:08.155Z,1637171708.155 [DAT](INFO): direction in vehicle frame: [ -0.551197 forward, -0.750364 starboard, 0.364877 keelward ]
2021-11-17T17:55:09.115Z,1637171709.115 [DAT](INFO): #Outgoing data=1
2021-11-17T17:55:09.115Z,1637171709.115 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-17T17:55:09.265Z,1637171709.265 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-17T17:55:12.889Z,1637171712.889 [DAT](INFO): DAT read: Forwarding Delay UpTx time:17:54:35.6550

2021-11-17T17:55:12.889Z,1637171712.889 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-17T17:55:21.770Z,1637171721.770 [DAT](INFO): DAT read: Rx Time:17:54:44.0303

2021-11-17T17:55:21.771Z,1637171721.771 [DAT](INFO): received an acoustic signal
2021-11-17T17:55:22.985Z,1637171722.985 [DAT](INFO): DAT read: 17:54:44.0303 LVL= 32752, 32753, 32754, 32755, AGC= 89, IDX= 182, 0.34,-2.632,-2.584,-2.634,-2.624, PHS=-0.012, 0.084,-0.024, RAW= 336.0,  -9.4, CAL= 337.1, -11.8, ROT= 232.9,  11.8

2021-11-17T17:55:22.986Z,1637171722.986 [DAT](INFO): got valid direction response:
 17:54:44.0303 LVL= 32752, 32753, 32754, 32755, AGC= 89, IDX= 182, 0.34,-2.632,-2.584,-2.634,-2.624, PHS=-0.012, 0.084,-0.024, RAW= 336.0,  -9.4, CAL= 337.1, -11.8, ROT= 232.9,  11.8

2021-11-17T17:55:22.987Z,1637171722.987 [DAT](INFO): DAT read: 

2021-11-17T17:55:22.988Z,1637171722.988 [DAT](INFO): DAT read: DATA(0002):~~

2021-11-17T17:55:22.988Z,1637171722.988 [DAT](INFO): Got DATA 2
2021-11-17T17:55:22.989Z,1637171722.989 [DAT](INFO): DAT read: Source:001  Destination:007

2021-11-17T17:55:22.989Z,1637171722.989 [DAT](INFO): Got Src/Dest after DATA 
2021-11-17T17:55:22.989Z,1637171722.989 [DAT](INFO): DATA Src=1, Dst=7
2021-11-17T17:55:22.991Z,1637171722.991 [DAT](INFO): DAT read: CRC:Pass MPD:03.7 PSNR:11.5 AGC:91 SPD:+0.1 CCERR:009

2021-11-17T17:55:22.991Z,1637171722.991 [DAT](INFO): Got CRC:Pass
2021-11-17T17:55:22.991Z,1637171722.991 [DAT](INFO): Got CRC:Pass
2021-11-17T17:55:22.991Z,1637171722.991 [DAT](INFO): Incoming data is intended for us
2021-11-17T17:55:22.991Z,1637171722.991 [DAT](DEBUG): In parseResponses, got ack so set commsState_ = SENDING_VERIFIED
2021-11-17T17:55:22.991Z,1637171722.991 [DAT](INFO): Got ack
2021-11-17T17:55:22.992Z,1637171722.992 [DAT](INFO): DAT read: 

2021-11-17T17:55:22.992Z,1637171722.992 [DAT](INFO): DAT read: <EOP>

2021-11-17T17:55:22.993Z,1637171722.993 [DAT](INFO): Sent 184 bytes from file Logs/20211117T175209/Courier0000.lzma.parts
2021-11-17T17:55:22.993Z,1637171722.993 [DAT](INFO): Packets left to send: 1
2021-11-17T17:55:22.995Z,1637171722.995 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-17T17:55:22.996Z,1637171722.996 [DAT](INFO): #Rx 3: Read direction message, but no range.
2021-11-17T17:55:22.997Z,1637171722.997 [DAT](INFO): direction in vehicle frame: [ -0.590461 forward, -0.780729 starboard, 0.204496 keelward ]
2021-11-17T17:55:24.418Z,1637171724.418 [DAT](INFO): #Outgoing data=1
2021-11-17T17:55:24.419Z,1637171724.419 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-17T17:55:24.589Z,1637171724.589 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-17T17:55:28.206Z,1637171728.206 [DAT](INFO): DAT read: Forwarding Delay UpTx time:17:54:50.8548

2021-11-17T17:55:28.206Z,1637171728.206 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-17T17:55:36.246Z,1637171736.246 [DAT](INFO): DAT read: Rx Time:17:54:58.4805

2021-11-17T17:55:36.246Z,1637171736.246 [DAT](INFO): received an acoustic signal
2021-11-17T17:55:37.075Z,1637171737.075 [DAT](INFO): DAT read: 17:54:58.4805 LVL= 32752, 32753, 32754, 32755, AGC= 89, IDX= 315,-0.06, 1.621, 1.669, 1.621, 1.615, PHS= 0.002, 0.098,-0.009, RAW= 335.3, -17.7, CAL= 336.9, -20.2, ROT= 233.1,  20.2

2021-11-17T17:55:37.076Z,1637171737.076 [DAT](INFO): got valid direction response:
 17:54:58.4805 LVL= 32752, 32753, 32754, 32755, AGC= 89, IDX= 315,-0.06, 1.621, 1.669, 1.621, 1.615, PHS= 0.002, 0.098,-0.009, RAW= 335.3, -17.7, CAL= 336.9, -20.2, ROT= 233.1,  20.2

2021-11-17T17:55:37.076Z,1637171737.076 [DAT](INFO): DAT read: 

2021-11-17T17:55:37.077Z,1637171737.077 [DAT](INFO): DAT read: DATA(0002):~~

2021-11-17T17:55:37.077Z,1637171737.077 [DAT](INFO): Got DATA 2
2021-11-17T17:55:37.078Z,1637171737.078 [DAT](INFO): #Rx 4: Read direction message, but no range.
2021-11-17T17:55:37.079Z,1637171737.079 [DAT](INFO): direction in vehicle frame: [ -0.563490 forward, -0.750499 starboard, 0.345298 keelward ]
2021-11-17T17:55:37.459Z,1637171737.459 [DAT](INFO): DAT read: Source:001  Destination:007

2021-11-17T17:55:37.459Z,1637171737.459 [DAT](INFO): Got Src/Dest after DATA 
2021-11-17T17:55:37.459Z,1637171737.459 [DAT](INFO): DATA Src=1, Dst=7
2021-11-17T17:55:37.461Z,1637171737.461 [DAT](INFO): DAT read: CRC:Pass MPD:03.8 PSNR:11.9 AGC:89 SPD:+0.1 CCERR:009

2021-11-17T17:55:37.461Z,1637171737.461 [DAT](INFO): Got CRC:Pass
2021-11-17T17:55:37.461Z,1637171737.461 [DAT](INFO): Got CRC:Pass
2021-11-17T17:55:37.461Z,1637171737.461 [DAT](INFO): Incoming data is intended for us
2021-11-17T17:55:37.461Z,1637171737.461 [DAT](DEBUG): In parseResponses, got ack so set commsState_ = SENDING_VERIFIED
2021-11-17T17:55:37.461Z,1637171737.461 [DAT](INFO): Got ack
2021-11-17T17:55:37.462Z,1637171737.462 [DAT](INFO): DAT read: 

2021-11-17T17:55:37.462Z,1637171737.462 [DAT](INFO): DAT read: <EOP>

2021-11-17T17:55:37.463Z,1637171737.463 [DAT](INFO): Sent 111 bytes from file Logs/20211117T175209/Courier0000.lzma.parts
2021-11-17T17:55:37.463Z,1637171737.463 [DAT](INFO): Packets left to send: 0
2021-11-17T17:55:37.489Z,1637171737.489 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-17T17:55:38.329Z,1637171738.329 [DAT](INFO): #Outgoing data=1
2021-11-17T17:55:38.329Z,1637171738.329 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-17T17:55:38.418Z,1637171738.418 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-17T17:55:40.051Z,1637171740.051 [Startup:StartupSatComms:B](INFO): Timed out from 2021-11-17T17:54:39.8Z
2021-11-17T17:55:40.052Z,1637171740.052 [Startup:StartupSatComms:B] Stopped
2021-11-17T17:55:40.052Z,1637171740.052 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2021-11-17T17:55:40.052Z,1637171740.052 [Startup:StartupSatComms] Stopped
2021-11-17T17:55:40.052Z,1637171740.052 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2021-11-17T17:55:40.053Z,1637171740.053 [Startup](INFO): Completed Startup
2021-11-17T17:55:40.053Z,1637171740.053 [MissionManager](INFO): Startup is completed.
2021-11-17T17:55:40.053Z,1637171740.053 [MissionManager](INFO): Uninitializing Mission Startup
2021-11-17T17:55:40.053Z,1637171740.053 [Startup] Stopped
2021-11-17T17:55:40.053Z,1637171740.053 [Startup](DEBUG): Aggregate::uninitialize Startup
2021-11-17T17:55:40.053Z,1637171740.053 [Startup:A.GoToSurface] Stopped
2021-11-17T17:55:40.054Z,1637171740.054 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2021-11-17T17:55:40.445Z,1637171740.445 [MissionManager](IMPORTANT): Started mission Default
2021-11-17T17:55:40.445Z,1637171740.445 [Default] Running Loop=1
2021-11-17T17:55:40.445Z,1637171740.445 [Default](DEBUG): Aggregate::initialize Default
2021-11-17T17:55:40.445Z,1637171740.445 [Default:B.GoToSurface] Running Loop=1
2021-11-17T17:55:40.446Z,1637171740.446 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2021-11-17T17:55:40.446Z,1637171740.446 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2021-11-17T17:55:40.446Z,1637171740.446 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2021-11-17T17:55:40.447Z,1637171740.447 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2021-11-17T17:55:40.447Z,1637171740.447 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2021-11-17T17:55:40.447Z,1637171740.447 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2021-11-17T17:55:40.448Z,1637171740.448 [Default:A.Wait] Running Loop=1
2021-11-17T17:55:40.448Z,1637171740.448 [Default:A.Wait](DEBUG): Initialize Wait Component.
2021-11-17T17:55:42.054Z,1637171742.054 [DAT](INFO): DAT read: Forwarding Delay UpTx time:17:55:04.8046

2021-11-17T17:55:42.055Z,1637171742.055 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-17T17:55:50.925Z,1637171750.925 [DAT](INFO): DAT read: Rx Time:17:55:13.2308

2021-11-17T17:55:50.925Z,1637171750.925 [DAT](INFO): received an acoustic signal
2021-11-17T17:55:52.138Z,1637171752.138 [DAT](INFO): DAT read: 17:55:13.2307 LVL= 32752, 32753, 32754, 32755, AGC= 90, IDX=  63, 0.42,-2.942,-2.897,-2.950,-2.953, PHS= 0.007, 0.100,-0.012, RAW= 339.1, -18.0, CAL= 340.4, -20.4, ROT= 229.6,  20.4

2021-11-17T17:55:52.139Z,1637171752.139 [DAT](INFO): got valid direction response:
 17:55:13.2307 LVL= 32752, 32753, 32754, 32755, AGC= 90, IDX=  63, 0.42,-2.942,-2.897,-2.950,-2.953, PHS= 0.007, 0.100,-0.012, RAW= 339.1, -18.0, CAL= 340.4, -20.4, ROT= 229.6,  20.4

2021-11-17T17:55:52.139Z,1637171752.139 [DAT](INFO): DAT read: 

2021-11-17T17:55:52.140Z,1637171752.140 [DAT](INFO): DAT read: DATA(0002):~~

2021-11-17T17:55:52.140Z,1637171752.140 [DAT](INFO): Got DATA 2
2021-11-17T17:55:52.141Z,1637171752.141 [DAT](INFO): DAT read: Source:001  Destination:007

2021-11-17T17:55:52.141Z,1637171752.141 [DAT](INFO): Got Src/Dest after DATA 
2021-11-17T17:55:52.142Z,1637171752.142 [DAT](INFO): DATA Src=1, Dst=7
2021-11-17T17:55:52.143Z,1637171752.143 [DAT](INFO): DAT read: CRC:Pass MPD:03.8 PSNR:12.2 AGC:89 SPD:-0.1 CCERR:010

2021-11-17T17:55:52.144Z,1637171752.144 [DAT](INFO): Got CRC:Pass
2021-11-17T17:55:52.144Z,1637171752.144 [DAT](INFO): Got CRC:Pass
2021-11-17T17:55:52.144Z,1637171752.144 [DAT](INFO): Incoming data is intended for us
2021-11-17T17:55:52.144Z,1637171752.144 [DAT](DEBUG): In parseResponses, got ack so set commsState_ = SENDING_VERIFIED
2021-11-17T17:55:52.144Z,1637171752.144 [DAT](INFO): Got ack
2021-11-17T17:55:52.145Z,1637171752.145 [DAT](INFO): DAT read: 

2021-11-17T17:55:52.145Z,1637171752.145 [DAT](INFO): DAT read: <EOP>

2021-11-17T17:55:52.146Z,1637171752.146 [DAT](INFO): Sent 184 bytes from file Logs/20211117T175209/Courier0900.lzma.parts
2021-11-17T17:55:52.146Z,1637171752.146 [DAT](INFO): Packets left to send: 27
2021-11-17T17:55:52.148Z,1637171752.148 [DAT](DEBUG): In sendingVerified, sbd done so set commsState_ = SENDING_FILL_BUFFER
2021-11-17T17:55:52.149Z,1637171752.149 [DAT](INFO): #Rx 5: Read direction message, but no range.
2021-11-17T17:55:52.150Z,1637171752.150 [DAT](INFO): direction in vehicle frame: [ -0.607471 forward, -0.713776 starboard, 0.348572 keelward ]
2021-11-17T17:55:53.817Z,1637171753.817 [Default:A.Wait](INFO): Done Waiting.
2021-11-17T17:55:53.817Z,1637171753.817 [Default:A.Wait] Stopped
2021-11-17T17:55:53.817Z,1637171753.817 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2021-11-17T17:55:54.182Z,1637171754.182 [Default:CheckIn] Running Loop=1
2021-11-17T17:55:54.182Z,1637171754.182 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-11-17T17:55:54.182Z,1637171754.182 [Default:CheckIn:Read_GPS] Running Loop=1
2021-11-17T17:55:54.594Z,1637171754.594 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2021-11-17T17:56:54.478Z,1637171814.478 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-11-17T17:55:54.2Z
2021-11-17T17:56:54.478Z,1637171814.478 [Default:CheckIn:Read_GPS] Stopped
2021-11-17T17:56:54.478Z,1637171814.478 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-11-17T17:56:54.938Z,1637171814.938 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2021-11-17T17:56:58.157Z,1637171818.157 [DAT](INFO): #Outgoing data=1
2021-11-17T17:56:58.157Z,1637171818.157 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-17T17:56:58.365Z,1637171818.365 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-17T17:57:01.807Z,1637171821.807 [DAT](INFO): DAT read: Forwarding Delay UpTx time:17:56:24.6035

2021-11-17T17:57:01.808Z,1637171821.808 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-17T17:57:09.061Z,1637171829.061 [DAT](INFO): DAT read: Rx Time:17:56:31.3821

2021-11-17T17:57:09.061Z,1637171829.061 [DAT](INFO): received an acoustic signal
2021-11-17T17:57:10.282Z,1637171830.282 [DAT](INFO): DAT read: 17:56:31.3821 LVL= 32752, 32753, 32754, 32755, AGC= 87, IDX= 457, 0.34,-2.694,-2.644,-2.695,-2.685, PHS=-0.013, 0.085,-0.026, RAW= 336.0,  -8.9, CAL= 337.1, -11.3, ROT= 232.9,  11.3

2021-11-17T17:57:10.292Z,1637171830.292 [DAT](INFO): got valid direction response:
 17:56:31.3821 LVL= 32752, 32753, 32754, 32755, AGC= 87, IDX= 457, 0.34,-2.694,-2.644,-2.695,-2.685, PHS=-0.013, 0.085,-0.026, RAW= 336.0,  -8.9, CAL= 337.1, -11.3, ROT= 232.9,  11.3

2021-11-17T17:57:10.292Z,1637171830.292 [DAT](INFO): DAT read: 

2021-11-17T17:57:10.293Z,1637171830.293 [DAT](INFO): DAT read: DATA(0002):~~

2021-11-17T17:57:10.293Z,1637171830.293 [DAT](INFO): Got DATA 2
2021-11-17T17:57:10.294Z,1637171830.294 [DAT](INFO): DAT read: Source:001  Destination:007

2021-11-17T17:57:10.294Z,1637171830.294 [DAT](INFO): Got Src/Dest after DATA 
2021-11-17T17:57:10.295Z,1637171830.295 [DAT](INFO): DATA Src=1, Dst=7
2021-11-17T17:57:10.301Z,1637171830.301 [DAT](INFO): DAT read: CRC:Pass MPD:03.8 PSNR:11.8 AGC:90 SPD:+0.0 CCERR:009

2021-11-17T17:57:10.301Z,1637171830.301 [DAT](INFO): Got CRC:Pass
2021-11-17T17:57:10.301Z,1637171830.301 [DAT](INFO): Got CRC:Pass
2021-11-17T17:57:10.301Z,1637171830.301 [DAT](INFO): Incoming data is intended for us
2021-11-17T17:57:10.302Z,1637171830.302 [DAT](DEBUG): In parseResponses, got ack so set commsState_ = SENDING_VERIFIED
2021-11-17T17:57:10.302Z,1637171830.302 [DAT](INFO): Got ack
2021-11-17T17:57:10.302Z,1637171830.302 [DAT](INFO): DAT read: 

2021-11-17T17:57:10.302Z,1637171830.302 [DAT](INFO): DAT read: <EOP>

2021-11-17T17:57:10.303Z,1637171830.303 [DAT](INFO): Sent 39 bytes from file Logs/20211117T175209/Courier0004.lzma.parts
2021-11-17T17:57:10.308Z,1637171830.308 [DAT](INFO): Packets left to send: 0
2021-11-17T17:57:10.310Z,1637171830.310 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-17T17:57:10.310Z,1637171830.310 [DAT](INFO): #Rx 6: Read direction message, but no range.
2021-11-17T17:57:10.364Z,1637171830.364 [DAT](INFO): direction in vehicle frame: [ -0.591515 forward, -0.782122 starboard, 0.195946 keelward ]
2021-11-17T17:57:11.848Z,1637171831.848 [DAT](INFO): #Outgoing data=1
2021-11-17T17:57:11.848Z,1637171831.848 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-17T17:57:11.973Z,1637171831.973 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-17T17:57:15.786Z,1637171835.786 [DAT](INFO): DAT read: Forwarding Delay UpTx time:17:56:38.3532

2021-11-17T17:57:15.787Z,1637171835.787 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-17T17:57:24.445Z,1637171844.445 [DAT](INFO): DAT read: Rx Time:17:56:46.7323

2021-11-17T17:57:24.445Z,1637171844.445 [DAT](INFO): received an acoustic signal
2021-11-17T17:57:25.669Z,1637171845.669 [DAT](INFO): DAT read: 17:56:46.7323 LVL= 32752, 32753, 32754, 32755, AGC= 89, IDX= 190, 0.15,-2.690,-2.639,-2.694,-2.682, PHS=-0.011, 0.087,-0.027, RAW= 337.2,  -9.1, CAL= 338.2, -11.6, ROT= 231.8,  11.6

2021-11-17T17:57:25.670Z,1637171845.670 [DAT](INFO): got valid direction response:
 17:56:46.7323 LVL= 32752, 32753, 32754, 32755, AGC= 89, IDX= 190, 0.15,-2.690,-2.639,-2.694,-2.682, PHS=-0.011, 0.087,-0.027, RAW= 337.2,  -9.1, CAL= 338.2, -11.6, ROT= 231.8,  11.6

2021-11-17T17:57:25.670Z,1637171845.670 [DAT](INFO): DAT read: 

2021-11-17T17:57:25.675Z,1637171845.675 [DAT](INFO): DAT read: DATA(0002):~~

2021-11-17T17:57:25.676Z,1637171845.676 [DAT](INFO): Got DATA 2
2021-11-17T17:57:25.677Z,1637171845.677 [DAT](INFO): DAT read: Source:001  Destination:007

2021-11-17T17:57:25.677Z,1637171845.677 [DAT](INFO): Got Src/Dest after DATA 
2021-11-17T17:57:25.677Z,1637171845.677 [DAT](INFO): DATA Src=1, Dst=7
2021-11-17T17:57:25.679Z,1637171845.679 [DAT](INFO): DAT read: CRC:Pass MPD:03.8 PSNR:12.2 AGC:89 SPD:+0.0 CCERR:010

2021-11-17T17:57:25.684Z,1637171845.684 [DAT](INFO): Got CRC:Pass
2021-11-17T17:57:25.685Z,1637171845.685 [DAT](INFO): Got CRC:Pass
2021-11-17T17:57:25.685Z,1637171845.685 [DAT](INFO): Incoming data is intended for us
2021-11-17T17:57:25.686Z,1637171845.686 [DAT](DEBUG): In parseResponses, got ack so set commsState_ = SENDING_VERIFIED
2021-11-17T17:57:25.687Z,1637171845.687 [DAT](INFO): Got ack
2021-11-17T17:57:25.692Z,1637171845.692 [DAT](INFO): DAT read: 

2021-11-17T17:57:25.692Z,1637171845.692 [DAT](INFO): DAT read: <EOP>

2021-11-17T17:57:25.693Z,1637171845.693 [DAT](INFO): Sent 184 bytes from file Logs/20211117T175209/Courier0900.lzma.parts
2021-11-17T17:57:25.693Z,1637171845.693 [DAT](INFO): Packets left to send: 26
2021-11-17T17:57:25.695Z,1637171845.695 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-17T17:57:25.700Z,1637171845.700 [DAT](INFO): #Rx 7: Read direction message, but no range.
2021-11-17T17:57:25.701Z,1637171845.701 [DAT](INFO): direction in vehicle frame: [ -0.605777 forward, -0.769806 starboard, 0.201078 keelward ]
2021-11-17T17:57:26.763Z,1637171846.763 [DAT](INFO): #Outgoing data=1
2021-11-17T17:57:26.764Z,1637171846.764 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-17T17:57:26.919Z,1637171846.919 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-17T17:57:30.522Z,1637171850.522 [DAT](INFO): DAT read: Forwarding Delay UpTx time:17:56:53.3030

2021-11-17T17:57:30.523Z,1637171850.523 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-17T17:57:39.418Z,1637171859.418 [DAT](INFO): DAT read: Rx Time:17:57:01.6826

2021-11-17T17:57:39.419Z,1637171859.419 [DAT](INFO): received an acoustic signal
2021-11-17T17:57:40.259Z,1637171860.259 [DAT](INFO): DAT read: 17:57:01.6825 LVL= 32752, 32753, 32754, 32755, AGC= 90, IDX= 195,-0.09, 1.835, 1.882, 1.832, 1.824, PHS= 0.006, 0.102,-0.008, RAW= 336.7, -19.0, CAL= 338.3, -21.4, ROT= 231.7,  21.4

2021-11-17T17:57:40.268Z,1637171860.268 [DAT](INFO): got valid direction response:
 17:57:01.6825 LVL= 32752, 32753, 32754, 32755, AGC= 90, IDX= 195,-0.09, 1.835, 1.882, 1.832, 1.824, PHS= 0.006, 0.102,-0.008, RAW= 336.7, -19.0, CAL= 338.3, -21.4, ROT= 231.7,  21.4

2021-11-17T17:57:40.269Z,1637171860.269 [DAT](INFO): DAT read: 

2021-11-17T17:57:40.270Z,1637171860.270 [DAT](INFO): DAT read: DATA(0002):~~

2021-11-17T17:57:40.270Z,1637171860.270 [DAT](INFO): Got DATA 2
2021-11-17T17:57:40.271Z,1637171860.271 [DAT](INFO): #Rx 8: Read direction message, but no range.
2021-11-17T17:57:40.277Z,1637171860.277 [DAT](INFO): direction in vehicle frame: [ -0.577049 forward, -0.730670 starboard, 0.364877 keelward ]
2021-11-17T17:57:40.634Z,1637171860.634 [DAT](INFO): DAT read: Source:001  Destination:007

2021-11-17T17:57:40.634Z,1637171860.634 [DAT](INFO): Got Src/Dest after DATA 
2021-11-17T17:57:40.634Z,1637171860.634 [DAT](INFO): DATA Src=1, Dst=7
2021-11-17T17:57:40.656Z,1637171860.656 [DAT](INFO): DAT read: CRC:Pass MPD:03.8 PSNR:12.0 AGC:89 SPD:-0.1 CCERR:010

2021-11-17T17:57:40.656Z,1637171860.656 [DAT](INFO): Got CRC:Pass
2021-11-17T17:57:40.656Z,1637171860.656 [DAT](INFO): Got CRC:Pass
2021-11-17T17:57:40.656Z,1637171860.656 [DAT](INFO): Incoming data is intended for us
2021-11-17T17:57:40.657Z,1637171860.657 [DAT](DEBUG): In parseResponses, got ack so set commsState_ = SENDING_VERIFIED
2021-11-17T17:57:40.657Z,1637171860.657 [DAT](INFO): Got ack
2021-11-17T17:57:40.657Z,1637171860.657 [DAT](INFO): DAT read: 

2021-11-17T17:57:40.657Z,1637171860.657 [DAT](INFO): DAT read: <EOP>

2021-11-17T17:57:40.658Z,1637171860.658 [DAT](INFO): Sent 184 bytes from file Logs/20211117T175209/Courier0900.lzma.parts
2021-11-17T17:57:40.658Z,1637171860.658 [DAT](INFO): Packets left to send: 25
2021-11-17T17:57:40.661Z,1637171860.661 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-17T17:57:41.821Z,1637171861.821 [DAT](INFO): #Outgoing data=1
2021-11-17T17:57:41.821Z,1637171861.821 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-17T17:57:41.938Z,1637171861.938 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-17T17:57:45.550Z,1637171865.550 [DAT](INFO): DAT read: Forwarding Delay UpTx time:17:57:08.3028

2021-11-17T17:57:45.550Z,1637171865.550 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-17T17:57:54.448Z,1637171874.448 [DAT](INFO): DAT read: Rx Time:17:57:16.6828

2021-11-17T17:57:54.448Z,1637171874.448 [DAT](INFO): received an acoustic signal
2021-11-17T17:57:55.842Z,1637171875.842 [DAT](INFO): DAT read: 17:57:16.6828 LVL= 32752, 32753, 32754, 32755, AGC= 89, IDX= 184,-0.35, 1.766, 1.821, 1.768, 1.777, PHS=-0.014, 0.089,-0.024, RAW= 334.3,  -9.3, CAL= 335.5, -11.8, ROT= 234.5,  11.8

2021-11-17T17:57:55.852Z,1637171875.852 [DAT](INFO): got valid direction response:
 17:57:16.6828 LVL= 32752, 32753, 32754, 32755, AGC= 89, IDX= 184,-0.35, 1.766, 1.821, 1.768, 1.777, PHS=-0.014, 0.089,-0.024, RAW= 334.3,  -9.3, CAL= 335.5, -11.8, ROT= 234.5,  11.8

2021-11-17T17:57:55.852Z,1637171875.852 [DAT](INFO): DAT read: 

2021-11-17T17:57:55.853Z,1637171875.853 [DAT](INFO): DAT read: DATA(0002):~~

2021-11-17T17:57:55.853Z,1637171875.853 [DAT](INFO): Got DATA 2
2021-11-17T17:57:55.854Z,1637171875.854 [DAT](INFO): DAT read: Source:001  Destination:007

2021-11-17T17:57:55.854Z,1637171875.854 [DAT](INFO): Got Src/Dest after DATA 
2021-11-17T17:57:55.855Z,1637171875.855 [DAT](INFO): DATA Src=1, Dst=7
2021-11-17T17:57:55.861Z,1637171875.861 [DAT](INFO): DAT read: CRC:Pass MPD:03.8 PSNR:12.1 AGC:88 SPD:+0.0 CCERR:010

2021-11-17T17:57:55.861Z,1637171875.861 [DAT](INFO): Got CRC:Pass
2021-11-17T17:57:55.861Z,1637171875.861 [DAT](INFO): Got CRC:Pass
2021-11-17T17:57:55.861Z,1637171875.861 [DAT](INFO): Incoming data is intended for us
2021-11-17T17:57:55.861Z,1637171875.861 [DAT](DEBUG): In parseResponses, got ack so set commsState_ = SENDING_VERIFIED
2021-11-17T17:57:55.861Z,1637171875.861 [DAT](INFO): Got ack
2021-11-17T17:57:55.862Z,1637171875.862 [DAT](INFO): DAT read: 

2021-11-17T17:57:55.862Z,1637171875.862 [DAT](INFO): DAT read: <EOP>

2021-11-17T17:57:55.863Z,1637171875.863 [DAT](INFO): Sent 184 bytes from file Logs/20211117T175209/Courier0900.lzma.parts
2021-11-17T17:57:55.863Z,1637171875.863 [DAT](INFO): Packets left to send: 24
2021-11-17T17:57:55.869Z,1637171875.869 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-17T17:57:55.869Z,1637171875.869 [DAT](INFO): #Rx 9: Read direction message, but no range.
2021-11-17T17:57:55.870Z,1637171875.870 [DAT](INFO): direction in vehicle frame: [ -0.568431 forward, -0.796911 starboard, 0.204496 keelward ]
2021-11-17T17:57:57.287Z,1637171877.287 [DAT](INFO): #Outgoing data=1
2021-11-17T17:57:57.288Z,1637171877.288 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-17T17:57:57.399Z,1637171877.399 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-17T17:58:01.013Z,1637171881.013 [DAT](INFO): DAT read: Forwarding Delay UpTx time:17:57:23.7525

2021-11-17T17:58:01.013Z,1637171881.013 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-17T17:58:03.017Z,1637171883.017 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2021-11-17T17:58:09.842Z,1637171889.842 [DAT](INFO): DAT read: Rx Time:17:57:32.1331

2021-11-17T17:58:09.843Z,1637171889.843 [DAT](INFO): received an acoustic signal
2021-11-17T17:58:10.956Z,1637171890.956 [DAT](INFO): DAT read: 17:57:32.1331 LVL= 32752, 32753, 32754, 32755, AGC= 87, IDX= 188, 0.48,-2.343,-2.257,-2.329,-2.282, PHS=-0.065, 0.069,-0.062, RAW= 328.9,   8.9, CAL= 329.0,   8.9, ROT= 241.0,  -8.9

2021-11-17T17:58:10.957Z,1637171890.957 [DAT](INFO): got valid direction response:
 17:57:32.1331 LVL= 32752, 32753, 32754, 32755, AGC= 87, IDX= 188, 0.48,-2.343,-2.257,-2.329,-2.282, PHS=-0.065, 0.069,-0.062, RAW= 328.9,   8.9, CAL= 329.0,   8.9, ROT= 241.0,  -8.9

2021-11-17T17:58:10.957Z,1637171890.957 [DAT](INFO): DAT read: 

2021-11-17T17:58:10.958Z,1637171890.958 [DAT](INFO): DAT read: DATA(0002):~~

2021-11-17T17:58:10.958Z,1637171890.958 [DAT](INFO): Got DATA 2
2021-11-17T17:58:10.959Z,1637171890.959 [DAT](INFO): DAT read: Source:001  Destination:007

2021-11-17T17:58:10.960Z,1637171890.960 [DAT](INFO): Got Src/Dest after DATA 
2021-11-17T17:58:10.960Z,1637171890.960 [DAT](INFO): DATA Src=1, Dst=7
2021-11-17T17:58:10.961Z,1637171890.961 [DAT](INFO): DAT read: CRC:Pass MPD:03.8 PSNR:11.8 AGC:87 SPD:+0.0 CCERR:010

2021-11-17T17:58:10.961Z,1637171890.961 [DAT](INFO): Got CRC:Pass
2021-11-17T17:58:10.962Z,1637171890.962 [DAT](INFO): Got CRC:Pass
2021-11-17T17:58:10.962Z,1637171890.962 [DAT](INFO): Incoming data is intended for us
2021-11-17T17:58:10.962Z,1637171890.962 [DAT](DEBUG): In parseResponses, got ack so set commsState_ = SENDING_VERIFIED
2021-11-17T17:58:10.962Z,1637171890.962 [DAT](INFO): Got ack
2021-11-17T17:58:10.962Z,1637171890.962 [DAT](INFO): DAT read: 

2021-11-17T17:58:10.963Z,1637171890.963 [DAT](INFO): DAT read: <EOP>

2021-11-17T17:58:10.964Z,1637171890.964 [DAT](INFO): Sent 184 bytes from file Logs/20211117T175209/Courier0900.lzma.parts
2021-11-17T17:58:10.964Z,1637171890.964 [DAT](INFO): Packets left to send: 23
2021-11-17T17:58:10.965Z,1637171890.965 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-17T17:58:10.966Z,1637171890.966 [DAT](INFO): #Rx 10: Read direction message, but no range.
2021-11-17T17:58:10.967Z,1637171890.967 [DAT](INFO): direction in vehicle frame: [ -0.478972 forward, -0.864089 starboard, -0.154710 keelward ]
2021-11-17T17:58:11.797Z,1637171891.797 [DAT](INFO): #Outgoing data=1
2021-11-17T17:58:11.797Z,1637171891.797 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-17T17:58:12.365Z,1637171892.365 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-17T17:58:15.969Z,1637171895.969 [DAT](INFO): DAT read: Forwarding Delay UpTx time:17:57:38.7522

2021-11-17T17:58:15.969Z,1637171895.969 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-17T17:58:25.934Z,1637171905.934 [DAT](INFO): DAT read: Rx Time:17:57:47.1833

2021-11-17T17:58:25.934Z,1637171905.934 [DAT](INFO): received an acoustic signal
2021-11-17T17:58:25.941Z,1637171905.941 [DAT](INFO): DAT read: 17:57:47.1833 LVL= 32752, 32753, 32754, 32755, AGC= 90, IDX= 193, 0.41,-2.936,-2.889,-2.938,-2.946, PHS= 0.006, 0.101,-0.007, RAW= 336.2, -19.2, CAL= 337.8, -21.6, ROT= 232.2,  21.6

2021-11-17T17:58:25.942Z,1637171905.942 [DAT](INFO): got valid direction response:
 17:57:47.1833 LVL= 32752, 32753, 32754, 32755, AGC= 90, IDX= 193, 0.41,-2.936,-2.889,-2.938,-2.946, PHS= 0.006, 0.101,-0.007, RAW= 336.2, -19.2, CAL= 337.8, -21.6, ROT= 232.2,  21.6

2021-11-17T17:58:25.943Z,1637171905.943 [DAT](INFO): DAT read: 

2021-11-17T17:58:25.944Z,1637171905.944 [DAT](INFO): DAT read: DATA(0002):~~

2021-11-17T17:58:25.944Z,1637171905.944 [DAT](INFO): Got DATA 2
2021-11-17T17:58:25.945Z,1637171905.945 [DAT](INFO): DAT read: Source:001  Destination:007

2021-11-17T17:58:25.945Z,1637171905.945 [DAT](INFO): Got Src/Dest after DATA 
2021-11-17T17:58:25.945Z,1637171905.945 [DAT](INFO): DATA Src=1, Dst=7
2021-11-17T17:58:25.947Z,1637171905.947 [DAT](INFO): DAT read: CRC:Pass MPD:03.7 PSNR:11.9 AGC:89 SPD:-0.1 CCERR:010

2021-11-17T17:58:25.947Z,1637171905.947 [DAT](INFO): Got CRC:Pass
2021-11-17T17:58:25.947Z,1637171905.947 [DAT](INFO): Got CRC:Pass
2021-11-17T17:58:25.947Z,1637171905.947 [DAT](INFO): Incoming data is intended for us
2021-11-17T17:58:25.947Z,1637171905.947 [DAT](DEBUG): In parseResponses, got ack so set commsState_ = SENDING_VERIFIED
2021-11-17T17:58:25.952Z,1637171905.952 [DAT](INFO): Got ack
2021-11-17T17:58:25.952Z,1637171905.952 [DAT](INFO): DAT read: 

2021-11-17T17:58:25.952Z,1637171905.952 [DAT](INFO): DAT read: <EOP>

2021-11-17T17:58:25.953Z,1637171905.953 [DAT](INFO): Sent 184 bytes from file Logs/20211117T175209/Courier0900.lzma.parts
2021-11-17T17:58:25.953Z,1637171905.953 [DAT](INFO): Packets left to send: 22
2021-11-17T17:58:25.955Z,1637171905.955 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-17T17:58:25.000Z,1637171906.000 [DAT](INFO): #Rx 11: Read direction message, but no range.
2021-11-17T17:58:26.001Z,1637171906.001 [DAT](INFO): direction in vehicle frame: [ -0.569867 forward, -0.734667 starboard, 0.368125 keelward ]
2021-11-17T17:58:26.001Z,1637171906.001 [DAT](INFO): not publishing receive ping time as it could be a packet for anyone
2021-11-17T17:58:27.216Z,1637171907.216 [DAT](INFO): #Outgoing data=1
2021-11-17T17:58:27.216Z,1637171907.216 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-17T17:58:27.346Z,1637171907.346 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-17T17:58:30.792Z,1637171910.792 [DAT](INFO): DAT read: Forwarding Delay UpTx time:17:57:53.7020

2021-11-17T17:58:30.793Z,1637171910.793 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-17T17:58:39.727Z,1637171919.727 [DAT](INFO): DAT read: Rx Time:17:58:02.1335

2021-11-17T17:58:39.727Z,1637171919.727 [DAT](INFO): received an acoustic signal
2021-11-17T17:58:40.910Z,1637171920.910 [DAT](INFO): DAT read: 17:58:02.1334 LVL= 32752, 32753, 32754, 32755, AGC= 89, IDX= 182, 0.17,-2.493,-2.439,-2.492,-2.482, PHS=-0.015, 0.087,-0.025, RAW= 334.6,  -8.6, CAL= 335.7, -11.0, ROT= 234.3,  11.0

2021-11-17T17:58:40.911Z,1637171920.911 [DAT](INFO): got valid direction response:
 17:58:02.1334 LVL= 32752, 32753, 32754, 32755, AGC= 89, IDX= 182, 0.17,-2.493,-2.439,-2.492,-2.482, PHS=-0.015, 0.087,-0.025, RAW= 334.6,  -8.6, CAL= 335.7, -11.0, ROT= 234.3,  11.0

2021-11-17T17:58:40.912Z,1637171920.912 [DAT](INFO): DAT read: 

2021-11-17T17:58:40.913Z,1637171920.913 [DAT](INFO): DAT read: DATA(0002):~~

2021-11-17T17:58:40.913Z,1637171920.913 [DAT](INFO): Got DATA 2
2021-11-17T17:58:40.914Z,1637171920.914 [DAT](INFO): DAT read: Source:001  Destination:007

2021-11-17T17:58:40.914Z,1637171920.914 [DAT](INFO): Got Src/Dest after DATA 
2021-11-17T17:58:40.914Z,1637171920.914 [DAT](INFO): DATA Src=1, Dst=7
2021-11-17T17:58:40.948Z,1637171920.948 [DAT](INFO): DAT read: CRC:Pass MPD:03.7 PSNR:11.6 AGC:89 SPD:+0.1 CCERR:010

2021-11-17T17:58:40.948Z,1637171920.948 [DAT](INFO): Got CRC:Pass
2021-11-17T17:58:40.948Z,1637171920.948 [DAT](INFO): Got CRC:Pass
2021-11-17T17:58:40.948Z,1637171920.948 [DAT](INFO): Incoming data is intended for us
2021-11-17T17:58:40.948Z,1637171920.948 [DAT](DEBUG): In parseResponses, got ack so set commsState_ = SENDING_VERIFIED
2021-11-17T17:58:40.949Z,1637171920.949 [DAT](INFO): Got ack
2021-11-17T17:58:40.949Z,1637171920.949 [DAT](INFO): DAT read: 

2021-11-17T17:58:40.949Z,1637171920.949 [DAT](INFO): DAT read: <EOP>

2021-11-17T17:58:40.950Z,1637171920.950 [DAT](INFO): Sent 184 bytes from file Logs/20211117T175209/Courier0900.lzma.parts
2021-11-17T17:58:40.950Z,1637171920.950 [DAT](INFO): Packets left to send: 21
2021-11-17T17:58:40.956Z,1637171920.956 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-17T17:58:40.956Z,1637171920.956 [DAT](INFO): #Rx 12: Read direction message, but no range.
2021-11-17T17:58:40.957Z,1637171920.957 [DAT](INFO): direction in vehicle frame: [ -0.572820 forward, -0.797163 starboard, 0.190809 keelward ]
2021-11-17T17:58:42.249Z,1637171922.249 [DAT](INFO): #Outgoing data=1
2021-11-17T17:58:42.249Z,1637171922.249 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-17T17:58:42.335Z,1637171922.335 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-17T17:58:46.041Z,1637171926.041 [DAT](INFO): DAT read: Forwarding Delay UpTx time:17:58:08.7018

2021-11-17T17:58:46.041Z,1637171926.041 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-17T17:58:55.365Z,1637171935.365 [DAT](INFO): DAT read: Rx Time:17:58:17.0836

2021-11-17T17:58:55.365Z,1637171935.365 [DAT](INFO): received an acoustic signal
2021-11-17T17:58:55.837Z,1637171935.837 [DAT](INFO): DAT read: 17:58:17.0836 LVL= 32752, 32753, 32754, 32755, AGC= 88, IDX= 187,-0.02, 2.729, 2.798, 2.738, 2.764, PHS=-0.039, 0.077,-0.041, RAW= 330.9,   0.5, CAL= 331.3,  -1.7, ROT= 238.7,   1.7

2021-11-17T17:58:55.838Z,1637171935.838 [DAT](INFO): got valid direction response:
 17:58:17.0836 LVL= 32752, 32753, 32754, 32755, AGC= 88, IDX= 187,-0.02, 2.729, 2.798, 2.738, 2.764, PHS=-0.039, 0.077,-0.041, RAW= 330.9,   0.5, CAL= 331.3,  -1.7, ROT= 238.7,   1.7

2021-11-17T17:58:55.838Z,1637171935.838 [DAT](INFO): DAT read: 

2021-11-17T17:58:55.839Z,1637171935.839 [DAT](INFO): DAT read: DATA(0002):~~

2021-11-17T17:58:55.839Z,1637171935.839 [DAT](INFO): Got DATA 2
2021-11-17T17:58:55.844Z,1637171935.844 [DAT](INFO): DAT read: Source:001  Destination:007

2021-11-17T17:58:55.844Z,1637171935.844 [DAT](INFO): Got Src/Dest after DATA 
2021-11-17T17:58:55.845Z,1637171935.845 [DAT](INFO): DATA Src=1, Dst=7
2021-11-17T17:58:55.846Z,1637171935.846 [DAT](INFO): DAT read: CRC:Pass MPD:03.8 PSNR:12.1 AGC:88 SPD:+0.0 CCERR:010

2021-11-17T17:58:55.846Z,1637171935.846 [DAT](INFO): Got CRC:Pass
2021-11-17T17:58:55.846Z,1637171935.846 [DAT](INFO): Got CRC:Pass
2021-11-17T17:58:55.847Z,1637171935.847 [DAT](INFO): Incoming data is intended for us
2021-11-17T17:58:55.847Z,1637171935.847 [DAT](DEBUG): In parseResponses, got ack so set commsState_ = SENDING_VERIFIED
2021-11-17T17:58:55.847Z,1637171935.847 [DAT](INFO): Got ack
2021-11-17T17:58:55.847Z,1637171935.847 [DAT](INFO): DAT read: 

2021-11-17T17:58:55.852Z,1637171935.852 [DAT](INFO): DAT read: <EOP>

2021-11-17T17:58:55.853Z,1637171935.853 [DAT](INFO): Sent 184 bytes from file Logs/20211117T175209/Courier0900.lzma.parts
2021-11-17T17:58:55.853Z,1637171935.853 [DAT](INFO): Packets left to send: 20
2021-11-17T17:58:55.854Z,1637171935.854 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-17T17:58:55.855Z,1637171935.855 [DAT](INFO): #Rx 13: Read direction message, but no range.
2021-11-17T17:58:55.860Z,1637171935.860 [DAT](INFO): direction in vehicle frame: [ -0.519290 forward, -0.854083 starboard, 0.029666 keelward ]
2021-11-17T17:58:57.011Z,1637171937.011 [DAT](INFO): #Outgoing data=1
2021-11-17T17:58:57.011Z,1637171937.011 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-17T17:58:57.151Z,1637171937.151 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-17T17:59:00.509Z,1637171940.509 [DAT](INFO): DAT read: Forwarding Delay UpTx time:17:58:23.5015

2021-11-17T17:59:00.509Z,1637171940.509 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-17T17:59:09.412Z,1637171949.412 [DAT](INFO): DAT read: Rx Time:17:58:31.8839

2021-11-17T17:59:09.412Z,1637171949.412 [DAT](INFO): received an acoustic signal
2021-11-17T17:59:10.618Z,1637171950.618 [DAT](INFO): DAT read: 17:58:31.8839 LVL= 32752, 32753, 32754, 32755, AGC= 89, IDX= 192,-0.13, 2.081, 2.135, 2.079, 2.089, PHS=-0.013, 0.090,-0.025, RAW= 335.8,  -9.5, CAL= 337.0, -11.9, ROT= 233.0,  11.9

2021-11-17T17:59:10.619Z,1637171950.619 [DAT](INFO): got valid direction response:
 17:58:31.8839 LVL= 32752, 32753, 32754, 32755, AGC= 89, IDX= 192,-0.13, 2.081, 2.135, 2.079, 2.089, PHS=-0.013, 0.090,-0.025, RAW= 335.8,  -9.5, CAL= 337.0, -11.9, ROT= 233.0,  11.9

2021-11-17T17:59:10.619Z,1637171950.619 [DAT](INFO): DAT read: 

2021-11-17T17:59:10.620Z,1637171950.620 [DAT](INFO): DAT read: DATA(0002):~~

2021-11-17T17:59:10.620Z,1637171950.620 [DAT](INFO): Got DATA 2
2021-11-17T17:59:10.621Z,1637171950.621 [DAT](INFO): DAT read: Source:001  Destination:007

2021-11-17T17:59:10.621Z,1637171950.621 [DAT](INFO): Got Src/Dest after DATA 
2021-11-17T17:59:10.622Z,1637171950.622 [DAT](INFO): DATA Src=1, Dst=7
2021-11-17T17:59:10.623Z,1637171950.623 [DAT](INFO): DAT read: CRC:Pass MPD:03.7 PSNR:12.0 AGC:90 SPD:+0.0 CCERR:010

2021-11-17T17:59:10.623Z,1637171950.623 [DAT](INFO): Got CRC:Pass
2021-11-17T17:59:10.624Z,1637171950.624 [DAT](INFO): Got CRC:Pass
2021-11-17T17:59:10.624Z,1637171950.624 [DAT](INFO): Incoming data is intended for us
2021-11-17T17:59:10.624Z,1637171950.624 [DAT](DEBUG): In parseResponses, got ack so set commsState_ = SENDING_VERIFIED
2021-11-17T17:59:10.624Z,1637171950.624 [DAT](INFO): Got ack
2021-11-17T17:59:10.624Z,1637171950.624 [DAT](INFO): DAT read: 

2021-11-17T17:59:10.625Z,1637171950.625 [DAT](INFO): DAT read: <EOP>

2021-11-17T17:59:10.625Z,1637171950.625 [DAT](INFO): Sent 184 bytes from file Logs/20211117T175209/Courier0900.lzma.parts
2021-11-17T17:59:10.626Z,1637171950.626 [DAT](INFO): Packets left to send: 19
2021-11-17T17:59:10.627Z,1637171950.627 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-17T17:59:10.628Z,1637171950.628 [DAT](INFO): #Rx 14: Read direction message, but no range.
2021-11-17T17:59:10.629Z,1637171950.629 [DAT](INFO): direction in vehicle frame: [ -0.588882 forward, -0.781472 starboard, 0.206204 keelward ]
2021-11-17T17:59:11.550Z,1637171951.550 [DAT](INFO): #Outgoing data=1
2021-11-17T17:59:11.550Z,1637171951.550 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-17T17:59:12.129Z,1637171952.129 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-17T17:59:15.699Z,1637171955.699 [DAT](INFO): DAT read: Forwarding Delay UpTx time:17:58:38.5013

2021-11-17T17:59:15.706Z,1637171955.706 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-17T17:59:24.885Z,1637171964.885 [DAT](INFO): DAT read: Rx Time:17:58:46.8841

2021-11-17T17:59:24.885Z,1637171964.885 [DAT](INFO): received an acoustic signal
2021-11-17T17:59:25.810Z,1637171965.810 [DAT](INFO): DAT read: 17:58:46.8841 LVL= 32752, 32753, 32754, 32755, AGC= 90, IDX= 181,-0.24, 1.190, 1.242, 1.193, 1.182, PHS= 0.004, 0.104,-0.005, RAW= 334.1, -19.3, CAL= 335.8, -21.7, ROT= 234.2,  21.7

2021-11-17T17:59:25.811Z,1637171965.811 [DAT](INFO): got valid direction response:
 17:58:46.8841 LVL= 32752, 32753, 32754, 32755, AGC= 90, IDX= 181,-0.24, 1.190, 1.242, 1.193, 1.182, PHS= 0.004, 0.104,-0.005, RAW= 334.1, -19.3, CAL= 335.8, -21.7, ROT= 234.2,  21.7

2021-11-17T17:59:25.811Z,1637171965.811 [DAT](INFO): DAT read: 

2021-11-17T17:59:25.812Z,1637171965.812 [DAT](INFO): DAT read: DATA(0002):~~

2021-11-17T17:59:25.812Z,1637171965.812 [DAT](INFO): Got DATA 2
2021-11-17T17:59:25.813Z,1637171965.813 [DAT](INFO): DAT read: Source:001  Destination:007

2021-11-17T17:59:25.813Z,1637171965.813 [DAT](INFO): Got Src/Dest after DATA 
2021-11-17T17:59:25.814Z,1637171965.814 [DAT](INFO): DATA Src=1, Dst=7
2021-11-17T17:59:25.815Z,1637171965.815 [DAT](INFO): DAT read: CRC:Pass MPD:03.8 PSNR:11.5 AGC:91 SPD:+0.1 CCERR:009

2021-11-17T17:59:25.815Z,1637171965.815 [DAT](INFO): Got CRC:Pass
2021-11-17T17:59:25.815Z,1637171965.815 [DAT](INFO): Got CRC:Pass
2021-11-17T17:59:25.816Z,1637171965.816 [DAT](INFO): Incoming data is intended for us
2021-11-17T17:59:25.816Z,1637171965.816 [DAT](DEBUG): In parseResponses, got ack so set commsState_ = SENDING_VERIFIED
2021-11-17T17:59:25.816Z,1637171965.816 [DAT](INFO): Got ack
2021-11-17T17:59:25.816Z,1637171965.816 [DAT](INFO): DAT read: 

2021-11-17T17:59:25.817Z,1637171965.817 [DAT](INFO): DAT read: <EOP>

2021-11-17T17:59:25.817Z,1637171965.817 [DAT](INFO): Sent 184 bytes from file Logs/20211117T175209/Courier0900.lzma.parts
2021-11-17T17:59:25.817Z,1637171965.817 [DAT](INFO): Packets left to send: 18
2021-11-17T17:59:25.819Z,1637171965.819 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-17T17:59:25.820Z,1637171965.820 [DAT](INFO): #Rx 15: Read direction message, but no range.
2021-11-17T17:59:25.821Z,1637171965.821 [DAT](INFO): direction in vehicle frame: [ -0.543503 forward, -0.753586 starboard, 0.369747 keelward ]
2021-11-17T17:59:26.700Z,1637171966.700 [DAT](INFO): #Outgoing data=1
2021-11-17T17:59:26.701Z,1637171966.701 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-17T17:59:27.277Z,1637171967.277 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-17T17:59:31.273Z,1637171971.273 [DAT](INFO): DAT read: Forwarding Delay UpTx time:17:58:53.6510

2021-11-17T17:59:31.273Z,1637171971.273 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-17T17:59:39.729Z,1637171979.729 [DAT](INFO): DAT read: Rx Time:17:59:02.0344

2021-11-17T17:59:39.729Z,1637171979.729 [DAT](INFO): received an acoustic signal
2021-11-17T17:59:40.613Z,1637171980.613 [DAT](INFO): DAT read: 17:59:02.0344 LVL= 32752, 32753, 32754, 32755, AGC= 89, IDX= 186,-0.39, 2.030, 2.086, 2.030, 2.037, PHS=-0.012, 0.093,-0.022, RAW= 334.7, -10.6, CAL= 336.0, -13.1, ROT= 234.0,  13.1

2021-11-17T17:59:40.615Z,1637171980.615 [DAT](INFO): got valid direction response:
 17:59:02.0344 LVL= 32752, 32753, 32754, 32755, AGC= 89, IDX= 186,-0.39, 2.030, 2.086, 2.030, 2.037, PHS=-0.012, 0.093,-0.022, RAW= 334.7, -10.6, CAL= 336.0, -13.1, ROT= 234.0,  13.1

2021-11-17T17:59:40.615Z,1637171980.615 [DAT](INFO): DAT read: 

2021-11-17T17:59:40.617Z,1637171980.617 [DAT](INFO): #Rx 16: Read direction message, but no range.
2021-11-17T17:59:40.618Z,1637171980.618 [DAT](INFO): direction in vehicle frame: [ -0.572489 forward, -0.787963 starboard, 0.226651 keelward ]
2021-11-17T17:59:40.982Z,1637171980.982 [DAT](INFO): DAT read: DATA(0002):~~

2021-11-17T17:59:40.982Z,1637171980.982 [DAT](INFO): Got DATA 2
2021-11-17T17:59:40.984Z,1637171980.984 [DAT](INFO): DAT read: Source:001  Destination:007

2021-11-17T17:59:40.984Z,1637171980.984 [DAT](INFO): Got Src/Dest after DATA 
2021-11-17T17:59:40.985Z,1637171980.985 [DAT](INFO): DATA Src=1, Dst=7
2021-11-17T17:59:40.986Z,1637171980.986 [DAT](INFO): DAT read: CRC:Pass MPD:03.8 PSNR:12.3 AGC:86 SPD:-0.1 CCERR:010

2021-11-17T17:59:40.986Z,1637171980.986 [DAT](INFO): Got CRC:Pass
2021-11-17T17:59:40.986Z,1637171980.986 [DAT](INFO): Got CRC:Pass
2021-11-17T17:59:40.987Z,1637171980.987 [DAT](INFO): Incoming data is intended for us
2021-11-17T17:59:40.987Z,1637171980.987 [DAT](DEBUG): In parseResponses, got ack so set commsState_ = SENDING_VERIFIED
2021-11-17T17:59:40.987Z,1637171980.987 [DAT](INFO): Got ack
2021-11-17T17:59:40.987Z,1637171980.987 [DAT](INFO): DAT read: 

2021-11-17T17:59:40.988Z,1637171980.988 [DAT](INFO): DAT read: <EOP>

2021-11-17T17:59:40.988Z,1637171980.988 [DAT](INFO): Sent 184 bytes from file Logs/20211117T175209/Courier0900.lzma.parts
2021-11-17T17:59:40.988Z,1637171980.988 [DAT](INFO): Packets left to send: 17
2021-11-17T17:59:40.990Z,1637171980.990 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-17T17:59:41.866Z,1637171981.866 [DAT](INFO): #Outgoing data=1
2021-11-17T17:59:41.867Z,1637171981.867 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-17T17:59:42.008Z,1637171982.008 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-17T17:59:46.198Z,1637171986.198 [DAT](INFO): DAT read: Forwarding Delay UpTx time:17:59:08.3508

2021-11-17T17:59:46.199Z,1637171986.199 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-17T17:59:49.079Z,1637171989.079 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2021-11-17T17:59:49.082Z,1637171989.082 [BPC1](INFO): Received data from all battery sticks.
2021-11-17T17:59:54.610Z,1637171994.610 [DAT](INFO): DAT read: Rx Time:17:59:16.7847

2021-11-17T17:59:54.610Z,1637171994.610 [DAT](INFO): received an acoustic signal
2021-11-17T17:59:55.429Z,1637171995.429 [DAT](INFO): DAT read: 17:59:16.7847 LVL= 32752, 32753, 32754, 32755, AGC= 88, IDX= 190, 0.25,-2.002,-1.933,-1.992,-1.965, PHS=-0.041, 0.076,-0.041, RAW= 330.2,   1.1, CAL= 330.6,  -1.2, ROT= 239.4,   1.2

2021-11-17T17:59:55.430Z,1637171995.430 [DAT](INFO): got valid direction response:
 17:59:16.7847 LVL= 32752, 32753, 32754, 32755, AGC= 88, IDX= 190, 0.25,-2.002,-1.933,-1.992,-1.965, PHS=-0.041, 0.076,-0.041, RAW= 330.2,   1.1, CAL= 330.6,  -1.2, ROT= 239.4,   1.2

2021-11-17T17:59:55.431Z,1637171995.431 [DAT](INFO): DAT read: 

2021-11-17T17:59:55.432Z,1637171995.432 [DAT](INFO): DAT read: DATA(0002):~~

2021-11-17T17:59:55.432Z,1637171995.432 [DAT](INFO): Got DATA 2
2021-11-17T17:59:55.433Z,1637171995.433 [DAT](INFO): DAT read: Source:001  Destination:007

2021-11-17T17:59:55.433Z,1637171995.433 [DAT](INFO): Got Src/Dest after DATA 
2021-11-17T17:59:55.434Z,1637171995.434 [DAT](INFO): DATA Src=1, Dst=7
2021-11-17T17:59:55.434Z,1637171995.434 [DAT](INFO): #Rx 17: Read direction message, but no range.
2021-11-17T17:59:55.435Z,1637171995.435 [DAT](INFO): direction in vehicle frame: [ -0.508930 forward, -0.860553 starboard, 0.020942 keelward ]
2021-11-17T17:59:55.829Z,1637171995.829 [DAT](INFO): DAT read: CRC:Pass MPD:03.7 PSNR:11.5 AGC:88 SPD:+0.1 CCERR:010

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

2021-11-17T17:59:55.831Z,1637171995.831 [DAT](INFO): DAT read: <EOP>

2021-11-17T17:59:55.832Z,1637171995.832 [DAT](INFO): Sent 184 bytes from file Logs/20211117T175209/Courier0900.lzma.parts
2021-11-17T17:59:55.832Z,1637171995.832 [DAT](INFO): Packets left to send: 16
2021-11-17T17:59:55.833Z,1637171995.833 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-17T17:59:57.184Z,1637171997.184 [DAT](INFO): #Outgoing data=1
2021-11-17T17:59:57.184Z,1637171997.184 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-17T17:59:57.270Z,1637171997.270 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-17T18:00:01.018Z,1637172001.018 [DAT](INFO): DAT read: Forwarding Delay UpTx time:17:59:23.6506

2021-11-17T18:00:01.018Z,1637172001.018 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-17T18:00:09.813Z,1637172009.813 [DAT](INFO): DAT read: Rx Time:17:59:32.0850

2021-11-17T18:00:09.813Z,1637172009.813 [DAT](INFO): received an acoustic signal
2021-11-17T18:00:10.739Z,1637172010.739 [DAT](INFO): DAT read: 17:59:32.0850 LVL= 32752, 32753, 32754, 32755, AGC= 87, IDX= 179, 0.19,-2.267,-2.181,-2.255,-2.206, PHS=-0.064, 0.069,-0.064, RAW= 329.8,   9.0, CAL= 330.0,   9.0, ROT= 240.0,  -9.0

2021-11-17T18:00:10.740Z,1637172010.740 [DAT](INFO): got valid direction response:
 17:59:32.0850 LVL= 32752, 32753, 32754, 32755, AGC= 87, IDX= 179, 0.19,-2.267,-2.181,-2.255,-2.206, PHS=-0.064, 0.069,-0.064, RAW= 329.8,   9.0, CAL= 330.0,   9.0, ROT= 240.0,  -9.0

2021-11-17T18:00:10.740Z,1637172010.740 [DAT](INFO): DAT read: 

2021-11-17T18:00:10.741Z,1637172010.741 [DAT](INFO): DAT read: DATA(0002):~~

2021-11-17T18:00:10.741Z,1637172010.741 [DAT](INFO): Got DATA 2
2021-11-17T18:00:10.742Z,1637172010.742 [DAT](INFO): DAT read: Source:001  Destination:007

2021-11-17T18:00:10.742Z,1637172010.742 [DAT](INFO): Got Src/Dest after DATA 
2021-11-17T18:00:10.743Z,1637172010.743 [DAT](INFO): DATA Src=1, Dst=7
2021-11-17T18:00:10.744Z,1637172010.744 [DAT](INFO): #Rx 18: Read direction message, but no range.
2021-11-17T18:00:10.745Z,1637172010.745 [DAT](INFO): direction in vehicle frame: [ -0.493844 forward, -0.855363 starboard, -0.156434 keelward ]
2021-11-17T18:00:11.129Z,1637172011.129 [DAT](INFO): DAT read: CRC:Pass MPD:03.7 PSNR:11.4 AGC:89 SPD:+0.1 CCERR:009

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

2021-11-17T18:00:11.131Z,1637172011.131 [DAT](INFO): DAT read: <EOP>

2021-11-17T18:00:11.131Z,1637172011.131 [DAT](INFO): Sent 184 bytes from file Logs/20211117T175209/Courier0900.lzma.parts
2021-11-17T18:00:11.132Z,1637172011.132 [DAT](INFO): Packets left to send: 15
2021-11-17T18:00:11.133Z,1637172011.133 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-17T18:00:12.479Z,1637172012.479 [DAT](INFO): #Outgoing data=1
2021-11-17T18:00:12.479Z,1637172012.479 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-17T18:00:12.567Z,1637172012.567 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-17T18:00:16.309Z,1637172016.309 [DAT](INFO): DAT read: Forwarding Delay UpTx time:17:59:38.9504

2021-11-17T18:00:16.309Z,1637172016.309 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-17T18:00:25.557Z,1637172025.557 [DAT](INFO): DAT read: Rx Time:17:59:47.3352

2021-11-17T18:00:25.557Z,1637172025.557 [DAT](INFO): received an acoustic signal
2021-11-17T18:00:26.076Z,1637172026.076 [DAT](INFO): DAT read: 17:59:47.3352 LVL= 32752, 32753, 32754, 32755, AGC= 87, IDX= 184, 0.21,-2.187,-2.106,-2.180,-2.133, PHS=-0.058, 0.070,-0.062, RAW= 331.3,   7.7, CAL= 331.5,   7.2, ROT= 238.5,  -7.2

2021-11-17T18:00:26.077Z,1637172026.077 [DAT](INFO): got valid direction response:
 17:59:47.3352 LVL= 32752, 32753, 32754, 32755, AGC= 87, IDX= 184, 0.21,-2.187,-2.106,-2.180,-2.133, PHS=-0.058, 0.070,-0.062, RAW= 331.3,   7.7, CAL= 331.5,   7.2, ROT= 238.5,  -7.2

2021-11-17T18:00:26.078Z,1637172026.078 [DAT](INFO): DAT read: 

2021-11-17T18:00:26.078Z,1637172026.078 [DAT](INFO): DAT read: DATA(0002):~~

2021-11-17T18:00:26.079Z,1637172026.079 [DAT](INFO): Got DATA 2
2021-11-17T18:00:26.080Z,1637172026.080 [DAT](INFO): DAT read: Source:001  Destination:007

2021-11-17T18:00:26.080Z,1637172026.080 [DAT](INFO): Got Src/Dest after DATA 
2021-11-17T18:00:26.080Z,1637172026.080 [DAT](INFO): DATA Src=1, Dst=7
2021-11-17T18:00:26.082Z,1637172026.082 [DAT](INFO): DAT read: CRC:Pass MPD:03.8 PSNR:12.1 AGC:89 SPD:+0.0 CCERR:010

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

2021-11-17T18:00:26.083Z,1637172026.083 [DAT](INFO): DAT read: <EOP>

2021-11-17T18:00:26.084Z,1637172026.084 [DAT](INFO): Sent 184 bytes from file Logs/20211117T175209/Courier0900.lzma.parts
2021-11-17T18:00:26.084Z,1637172026.084 [DAT](INFO): Packets left to send: 14
2021-11-17T18:00:26.086Z,1637172026.086 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-17T18:00:26.086Z,1637172026.086 [DAT](INFO): #Rx 19: Read direction message, but no range.
2021-11-17T18:00:26.111Z,1637172026.111 [DAT](INFO): direction in vehicle frame: [ -0.518379 forward, -0.845917 starboard, -0.125333 keelward ]
2021-11-17T18:00:27.422Z,1637172027.422 [DAT](INFO): #Outgoing data=1
2021-11-17T18:00:27.422Z,1637172027.422 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-17T18:00:27.530Z,1637172027.530 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-17T18:00:31.069Z,1637172031.069 [DAT](INFO): DAT read: Forwarding Delay UpTx time:17:59:53.9001

2021-11-17T18:00:31.069Z,1637172031.069 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-17T18:00:39.926Z,1637172039.926 [DAT](INFO): DAT read: Rx Time:18:00:02.2855

2021-11-17T18:00:39.926Z,1637172039.926 [DAT](INFO): received an acoustic signal
2021-11-17T18:00:41.142Z,1637172041.142 [DAT](INFO): DAT read: 18:00:02.2855 LVL= 32752, 32753, 32754, 32755, AGC= 90, IDX= 189, 0.19, 3.042, 3.088, 3.041, 3.032, PHS= 0.006, 0.101,-0.006, RAW= 336.1, -19.5, CAL= 337.7, -21.8, ROT= 232.3,  21.8

2021-11-17T18:00:41.143Z,1637172041.143 [DAT](INFO): got valid direction response:
 18:00:02.2855 LVL= 32752, 32753, 32754, 32755, AGC= 90, IDX= 189, 0.19, 3.042, 3.088, 3.041, 3.032, PHS= 0.006, 0.101,-0.006, RAW= 336.1, -19.5, CAL= 337.7, -21.8, ROT= 232.3,  21.8

2021-11-17T18:00:41.143Z,1637172041.143 [DAT](INFO): DAT read: 

2021-11-17T18:00:41.144Z,1637172041.144 [DAT](INFO): DAT read: DATA(0002):~~

2021-11-17T18:00:41.144Z,1637172041.144 [DAT](INFO): Got DATA 2
2021-11-17T18:00:41.145Z,1637172041.145 [DAT](INFO): DAT read: Source:001  Destination:007

2021-11-17T18:00:41.145Z,1637172041.145 [DAT](INFO): Got Src/Dest after DATA 
2021-11-17T18:00:41.145Z,1637172041.145 [DAT](INFO): DATA Src=1, Dst=7
2021-11-17T18:00:41.147Z,1637172041.147 [DAT](INFO): DAT read: CRC:Pass MPD:03.7 PSNR:11.9 AGC:90 SPD:+0.0 CCERR:010

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

2021-11-17T18:00:41.148Z,1637172041.148 [DAT](INFO): DAT read: <EOP>

2021-11-17T18:00:41.149Z,1637172041.149 [DAT](INFO): Sent 184 bytes from file Logs/20211117T175209/Courier0900.lzma.parts
2021-11-17T18:00:41.149Z,1637172041.149 [DAT](INFO): Packets left to send: 13
2021-11-17T18:00:41.172Z,1637172041.172 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-17T18:00:41.172Z,1637172041.172 [DAT](INFO): #Rx 20: Read direction message, but no range.
2021-11-17T18:00:41.173Z,1637172041.173 [DAT](INFO): direction in vehicle frame: [ -0.567794 forward, -0.734640 starboard, 0.371368 keelward ]
2021-11-17T18:00:42.054Z,1637172042.054 [DAT](INFO): #Outgoing data=1
2021-11-17T18:00:42.054Z,1637172042.054 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-17T18:00:42.157Z,1637172042.157 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-17T18:00:45.610Z,1637172045.610 [DAT](INFO): DAT read: Forwarding Delay UpTx time:18:00:08.5500

2021-11-17T18:00:45.610Z,1637172045.610 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-17T18:00:54.537Z,1637172054.537 [DAT](INFO): DAT read: Rx Time:18:00:16.9357

2021-11-17T18:00:54.538Z,1637172054.538 [DAT](INFO): received an acoustic signal
2021-11-17T18:00:56.711Z,1637172056.711 [DAT](INFO): DAT read: 18:00:16.9357 LVL= 32752, 32753, 32754, 32755, AGC= 90, IDX= 194, 0.11,-2.826,-2.778,-2.828,-2.837, PHS= 0.007, 0.103,-0.007, RAW= 336.3, -19.4, CAL= 337.8, -21.7, ROT= 232.2,  21.7

2021-11-17T18:00:56.712Z,1637172056.712 [DAT](INFO): got valid direction response:
 18:00:16.9357 LVL= 32752, 32753, 32754, 32755, AGC= 90, IDX= 194, 0.11,-2.826,-2.778,-2.828,-2.837, PHS= 0.007, 0.103,-0.007, RAW= 336.3, -19.4, CAL= 337.8, -21.7, ROT= 232.2,  21.7

2021-11-17T18:00:56.712Z,1637172056.712 [DAT](INFO): DAT read: 

2021-11-17T18:00:56.713Z,1637172056.713 [DAT](INFO): DAT read: DATA(0002):~~

2021-11-17T18:00:56.713Z,1637172056.713 [DAT](INFO): Got DATA 2
2021-11-17T18:00:56.714Z,1637172056.714 [DAT](INFO): DAT read: Source:001  Destination:007

2021-11-17T18:00:56.714Z,1637172056.714 [DAT](INFO): Got Src/Dest after DATA 
2021-11-17T18:00:56.715Z,1637172056.715 [DAT](INFO): DATA Src=1, Dst=7
2021-11-17T18:00:56.754Z,1637172056.754 [DAT](INFO): DAT read: CRC:Pass MPD:03.8 PSNR:12.2 AGC:87 SPD:-0.1 CCERR:010

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

2021-11-17T18:00:56.755Z,1637172056.755 [DAT](INFO): DAT read: <EOP>

2021-11-17T18:00:56.760Z,1637172056.760 [DAT](INFO): Sent 184 bytes from file Logs/20211117T175209/Courier0900.lzma.parts
2021-11-17T18:00:56.760Z,1637172056.760 [DAT](INFO): Packets left to send: 12
2021-11-17T18:00:56.762Z,1637172056.762 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-17T18:00:56.762Z,1637172056.762 [DAT](INFO): #Rx 21: Read direction message, but no range.
2021-11-17T18:00:56.768Z,1637172056.768 [DAT](INFO): direction in vehicle frame: [ -0.569472 forward, -0.734159 starboard, 0.369747 keelward ]
2021-11-17T18:00:57.668Z,1637172057.668 [DAT](INFO): #Outgoing data=1
2021-11-17T18:00:57.668Z,1637172057.668 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-17T18:00:57.753Z,1637172057.753 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-17T18:01:01.490Z,1637172061.490 [DAT](INFO): DAT read: Forwarding Delay UpTx time:18:00:24.0998

2021-11-17T18:01:01.491Z,1637172061.491 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-17T18:01:10.018Z,1637172070.018 [DAT](INFO): DAT read: Rx Time:18:00:32.4860

2021-11-17T18:01:10.019Z,1637172070.019 [DAT](INFO): received an acoustic signal
2021-11-17T18:01:11.218Z,1637172071.218 [DAT](INFO): DAT read: 18:00:32.4860 LVL= 32752, 32753, 32754, 32755, AGC= 90, IDX= 184,-0.37, 1.388, 1.436, 1.381, 1.381, PHS= 0.004, 0.099,-0.015, RAW= 338.8, -16.3, CAL= 340.1, -18.9, ROT= 229.9,  18.9

2021-11-17T18:01:11.220Z,1637172071.220 [DAT](INFO): got valid direction response:
 18:00:32.4860 LVL= 32752, 32753, 32754, 32755, AGC= 90, IDX= 184,-0.37, 1.388, 1.436, 1.381, 1.381, PHS= 0.004, 0.099,-0.015, RAW= 338.8, -16.3, CAL= 340.1, -18.9, ROT= 229.9,  18.9

2021-11-17T18:01:11.220Z,1637172071.220 [DAT](INFO): DAT read: 

2021-11-17T18:01:11.221Z,1637172071.221 [DAT](INFO): DAT read: DATA(0002):~~

2021-11-17T18:01:11.221Z,1637172071.221 [DAT](INFO): Got DATA 2
2021-11-17T18:01:11.222Z,1637172071.222 [DAT](INFO): DAT read: Source:001  Destination:007

2021-11-17T18:01:11.222Z,1637172071.222 [DAT](INFO): Got Src/Dest after DATA 
2021-11-17T18:01:11.223Z,1637172071.223 [DAT](INFO): DATA Src=1, Dst=7
2021-11-17T18:01:11.224Z,1637172071.224 [DAT](INFO): DAT read: CRC:Pass MPD:03.8 PSNR:11.7 AGC:89 SPD:+0.1 CCERR:010

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

2021-11-17T18:01:11.226Z,1637172071.226 [DAT](INFO): DAT read: <EOP>

2021-11-17T18:01:11.226Z,1637172071.226 [DAT](INFO): Sent 184 bytes from file Logs/20211117T175209/Courier0900.lzma.parts
2021-11-17T18:01:11.226Z,1637172071.226 [DAT](INFO): Packets left to send: 11
2021-11-17T18:01:11.228Z,1637172071.228 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-17T18:01:11.229Z,1637172071.229 [DAT](INFO): #Rx 22: Read direction message, but no range.
2021-11-17T18:01:11.230Z,1637172071.230 [DAT](INFO): direction in vehicle frame: [ -0.609396 forward, -0.723681 starboard, 0.323917 keelward ]
2021-11-17T18:01:12.558Z,1637172072.558 [DAT](INFO): #Outgoing data=1
2021-11-17T18:01:12.559Z,1637172072.559 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-17T18:01:12.641Z,1637172072.641 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-17T18:01:16.397Z,1637172076.397 [DAT](INFO): DAT read: Forwarding Delay UpTx time:18:00:38.9995

2021-11-17T18:01:16.397Z,1637172076.397 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-17T18:01:24.939Z,1637172084.939 [DAT](INFO): DAT read: Rx Time:18:00:47.3863

2021-11-17T18:01:24.939Z,1637172084.939 [DAT](INFO): received an acoustic signal
2021-11-17T18:01:26.147Z,1637172086.147 [DAT](INFO): DAT read: 18:00:47.3862 LVL= 32752, 32753, 32754, 32755, AGC= 89, IDX= 189,-0.19, 1.943, 2.004, 1.948, 1.958, PHS=-0.019, 0.089,-0.026, RAW= 333.1,  -8.1, CAL= 334.2, -10.5, ROT= 235.8,  10.5

2021-11-17T18:01:26.149Z,1637172086.149 [DAT](INFO): got valid direction response:
 18:00:47.3862 LVL= 32752, 32753, 32754, 32755, AGC= 89, IDX= 189,-0.19, 1.943, 2.004, 1.948, 1.958, PHS=-0.019, 0.089,-0.026, RAW= 333.1,  -8.1, CAL= 334.2, -10.5, ROT= 235.8,  10.5

2021-11-17T18:01:26.149Z,1637172086.149 [DAT](INFO): DAT read: 

2021-11-17T18:01:26.150Z,1637172086.150 [DAT](INFO): DAT read: DATA(0002):~~

2021-11-17T18:01:26.150Z,1637172086.150 [DAT](INFO): Got DATA 2
2021-11-17T18:01:26.151Z,1637172086.151 [DAT](INFO): DAT read: Source:001  Destination:007

2021-11-17T18:01:26.151Z,1637172086.151 [DAT](INFO): Got Src/Dest after DATA 
2021-11-17T18:01:26.151Z,1637172086.151 [DAT](INFO): DATA Src=1, Dst=7
2021-11-17T18:01:26.153Z,1637172086.153 [DAT](INFO): DAT read: CRC:Pass MPD:03.8 PSNR:12.1 AGC:88 SPD:+0.0 CCERR:010

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

2021-11-17T18:01:26.154Z,1637172086.154 [DAT](INFO): DAT read: <EOP>

2021-11-17T18:01:26.155Z,1637172086.155 [DAT](INFO): Sent 184 bytes from file Logs/20211117T175209/Courier0900.lzma.parts
2021-11-17T18:01:26.155Z,1637172086.155 [DAT](INFO): Packets left to send: 10
2021-11-17T18:01:26.157Z,1637172086.157 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-17T18:01:26.158Z,1637172086.158 [DAT](INFO): #Rx 23: Read direction message, but no range.
2021-11-17T18:01:26.159Z,1637172086.159 [DAT](INFO): direction in vehicle frame: [ -0.552671 forward, -0.813231 starboard, 0.182236 keelward ]
2021-11-17T18:01:27.022Z,1637172087.022 [DAT](INFO): #Outgoing data=1
2021-11-17T18:01:27.022Z,1637172087.022 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-17T18:01:27.119Z,1637172087.119 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-17T18:01:31.329Z,1637172091.329 [DAT](INFO): DAT read: Forwarding Delay UpTx time:18:00:53.4992

2021-11-17T18:01:31.329Z,1637172091.329 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-17T18:01:39.718Z,1637172099.718 [DAT](INFO): DAT read: Rx Time:18:01:01.8865

2021-11-17T18:01:39.719Z,1637172099.719 [DAT](INFO): received an acoustic signal
2021-11-17T18:01:40.536Z,1637172100.536 [DAT](INFO): DAT read: 18:01:01.8865 LVL= 32752, 32753, 32754, 32755, AGC= 89, IDX= 194,-0.23, 1.430, 1.486, 1.431, 1.439, PHS=-0.013, 0.091,-0.023, RAW= 334.5, -10.0, CAL= 335.7, -12.5, ROT= 234.3,  12.5

2021-11-17T18:01:40.537Z,1637172100.537 [DAT](INFO): got valid direction response:
 18:01:01.8865 LVL= 32752, 32753, 32754, 32755, AGC= 89, IDX= 194,-0.23, 1.430, 1.486, 1.431, 1.439, PHS=-0.013, 0.091,-0.023, RAW= 334.5, -10.0, CAL= 335.7, -12.5, ROT= 234.3,  12.5

2021-11-17T18:01:40.537Z,1637172100.537 [DAT](INFO): DAT read: 

2021-11-17T18:01:40.538Z,1637172100.538 [DAT](INFO): DAT read: DATA(0002):~~

2021-11-17T18:01:40.539Z,1637172100.539 [DAT](INFO): Got DATA 2
2021-11-17T18:01:40.540Z,1637172100.540 [DAT](INFO): DAT read: Source:001  Destination:007

2021-11-17T18:01:40.540Z,1637172100.540 [DAT](INFO): Got Src/Dest after DATA 
2021-11-17T18:01:40.541Z,1637172100.541 [DAT](INFO): DATA Src=1, Dst=7
2021-11-17T18:01:40.541Z,1637172100.541 [DAT](INFO): #Rx 24: Read direction message, but no range.
2021-11-17T18:01:40.542Z,1637172100.542 [DAT](INFO): direction in vehicle frame: [ -0.569709 forward, -0.792834 starboard, 0.216440 keelward ]
2021-11-17T18:01:40.946Z,1637172100.946 [DAT](INFO): DAT read: CRC:Pass MPD:03.8 PSNR:12.1 AGC:89 SPD:-0.1 CCERR:010

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

2021-11-17T18:01:40.947Z,1637172100.947 [DAT](INFO): DAT read: <EOP>

2021-11-17T18:01:40.948Z,1637172100.948 [DAT](INFO): Sent 184 bytes from file Logs/20211117T175209/Courier0900.lzma.parts
2021-11-17T18:01:40.948Z,1637172100.948 [DAT](INFO): Packets left to send: 9
2021-11-17T18:01:40.950Z,1637172100.950 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-17T18:01:42.257Z,1637172102.257 [DAT](INFO): #Outgoing data=1
2021-11-17T18:01:42.257Z,1637172102.257 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-17T18:01:42.343Z,1637172102.343 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-17T18:01:46.046Z,1637172106.046 [DAT](INFO): DAT read: Forwarding Delay UpTx time:18:01:08.6990

2021-11-17T18:01:46.047Z,1637172106.047 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-17T18:01:54.841Z,1637172114.841 [DAT](INFO): DAT read: Rx Time:18:01:17.0867

2021-11-17T18:01:54.841Z,1637172114.841 [DAT](INFO): received an acoustic signal
2021-11-17T18:01:55.763Z,1637172115.763 [DAT](INFO): DAT read: 18:01:17.0867 LVL= 32752, 32753, 32754, 32755, AGC= 89, IDX= 183,-0.05, 1.874, 1.931, 1.874, 1.882, PHS=-0.012, 0.093,-0.023, RAW= 334.8, -10.4, CAL= 336.1, -12.9, ROT= 233.9,  12.9

2021-11-17T18:01:55.764Z,1637172115.764 [DAT](INFO): got valid direction response:
 18:01:17.0867 LVL= 32752, 32753, 32754, 32755, AGC= 89, IDX= 183,-0.05, 1.874, 1.931, 1.874, 1.882, PHS=-0.012, 0.093,-0.023, RAW= 334.8, -10.4, CAL= 336.1, -12.9, ROT= 233.9,  12.9

2021-11-17T18:01:55.765Z,1637172115.765 [DAT](INFO): DAT read: 

2021-11-17T18:01:55.766Z,1637172115.766 [DAT](INFO): DAT read: DATA(0002):~~

2021-11-17T18:01:55.766Z,1637172115.766 [DAT](INFO): Got DATA 2
2021-11-17T18:01:55.767Z,1637172115.767 [DAT](INFO): DAT read: Source:001  Destination:007

2021-11-17T18:01:55.767Z,1637172115.767 [DAT](INFO): Got Src/Dest after DATA 
2021-11-17T18:01:55.768Z,1637172115.768 [DAT](INFO): DATA Src=1, Dst=7
2021-11-17T18:01:55.769Z,1637172115.769 [DAT](INFO): DAT read: CRC:Pass MPD:03.8 PSNR:11.7 AGC:86 SPD:+0.1 CCERR:010

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

2021-11-17T18:01:55.771Z,1637172115.771 [DAT](INFO): DAT read: <EOP>

2021-11-17T18:01:55.772Z,1637172115.772 [DAT](INFO): Sent 184 bytes from file Logs/20211117T175209/Courier0900.lzma.parts
2021-11-17T18:01:55.772Z,1637172115.772 [DAT](INFO): Packets left to send: 8
2021-11-17T18:01:55.773Z,1637172115.773 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-17T18:01:55.774Z,1637172115.774 [DAT](INFO): #Rx 25: Read direction message, but no range.
2021-11-17T18:01:55.775Z,1637172115.775 [DAT](INFO): direction in vehicle frame: [ -0.574326 forward, -0.787597 starboard, 0.223250 keelward ]
2021-11-17T18:01:56.659Z,1637172116.659 [DAT](INFO): #Outgoing data=1
2021-11-17T18:01:56.659Z,1637172116.659 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-17T18:01:57.212Z,1637172117.212 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-17T18:02:01.154Z,1637172121.154 [DAT](INFO): DAT read: Forwarding Delay UpTx time:18:01:23.5987

2021-11-17T18:02:01.154Z,1637172121.154 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-17T18:02:09.601Z,1637172129.601 [DAT](INFO): DAT read: Rx Time:18:01:31.9870

2021-11-17T18:02:09.601Z,1637172129.601 [DAT](INFO): received an acoustic signal
2021-11-17T18:02:10.908Z,1637172130.908 [DAT](INFO): DAT read: 18:01:31.9869 LVL= 32752, 32753, 32754, 32755, AGC= 89, IDX= 188, 0.07, 2.938, 2.992, 2.936, 2.948, PHS=-0.014, 0.088,-0.027, RAW= 335.9,  -8.8, CAL= 337.0, -11.2, ROT= 233.0,  11.2

2021-11-17T18:02:10.909Z,1637172130.909 [DAT](INFO): got valid direction response:
 18:01:31.9869 LVL= 32752, 32753, 32754, 32755, AGC= 89, IDX= 188, 0.07, 2.938, 2.992, 2.936, 2.948, PHS=-0.014, 0.088,-0.027, RAW= 335.9,  -8.8, CAL= 337.0, -11.2, ROT= 233.0,  11.2

2021-11-17T18:02:10.909Z,1637172130.909 [DAT](INFO): DAT read: 

2021-11-17T18:02:10.910Z,1637172130.910 [DAT](INFO): DAT read: DATA(0002):~~

2021-11-17T18:02:10.910Z,1637172130.910 [DAT](INFO): Got DATA 2
2021-11-17T18:02:10.911Z,1637172130.911 [DAT](INFO): DAT read: Source:001  Destination:007

2021-11-17T18:02:10.911Z,1637172130.911 [DAT](INFO): Got Src/Dest after DATA 
2021-11-17T18:02:10.912Z,1637172130.912 [DAT](INFO): DATA Src=1, Dst=7
2021-11-17T18:02:10.913Z,1637172130.913 [DAT](INFO): DAT read: CRC:Pass MPD:03.7 PSNR:12.5 AGC:89 SPD:+0.0 CCERR:010

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

2021-11-17T18:02:10.914Z,1637172130.914 [DAT](INFO): DAT read: <EOP>

2021-11-17T18:02:10.915Z,1637172130.915 [DAT](INFO): Sent 184 bytes from file Logs/20211117T175209/Courier0900.lzma.parts
2021-11-17T18:02:10.915Z,1637172130.915 [DAT](INFO): Packets left to send: 7
2021-11-17T18:02:10.917Z,1637172130.917 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-17T18:02:10.917Z,1637172130.917 [DAT](INFO): #Rx 26: Read direction message, but no range.
2021-11-17T18:02:10.918Z,1637172130.918 [DAT](INFO): direction in vehicle frame: [ -0.590354 forward, -0.783426 starboard, 0.194234 keelward ]
2021-11-17T18:02:11.806Z,1637172131.806 [DAT](INFO): #Outgoing data=1
2021-11-17T18:02:11.806Z,1637172131.806 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-17T18:02:11.898Z,1637172131.898 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-17T18:02:16.105Z,1637172136.105 [DAT](INFO): DAT read: Forwarding Delay UpTx time:18:01:38.2485

2021-11-17T18:02:16.105Z,1637172136.105 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-17T18:02:24.258Z,1637172144.258 [DAT](INFO): DAT read: Rx Time:18:01:46.6372

2021-11-17T18:02:24.258Z,1637172144.258 [DAT](INFO): received an acoustic signal
2021-11-17T18:02:25.476Z,1637172145.476 [DAT](INFO): DAT read: 18:01:46.6372 LVL= 32752, 32753, 32754, 32755, AGC= 89, IDX= 193, 0.15,-2.731,-2.673,-2.728,-2.715, PHS=-0.021, 0.086,-0.028, RAW= 333.3,  -6.8, CAL= 334.3,  -9.2, ROT= 235.7,   9.2

2021-11-17T18:02:25.477Z,1637172145.477 [DAT](INFO): got valid direction response:
 18:01:46.6372 LVL= 32752, 32753, 32754, 32755, AGC= 89, IDX= 193, 0.15,-2.731,-2.673,-2.728,-2.715, PHS=-0.021, 0.086,-0.028, RAW= 333.3,  -6.8, CAL= 334.3,  -9.2, ROT= 235.7,   9.2

2021-11-17T18:02:25.478Z,1637172145.478 [DAT](INFO): DAT read: 

2021-11-17T18:02:25.478Z,1637172145.478 [DAT](INFO): DAT read: DATA(0002):~~

2021-11-17T18:02:25.479Z,1637172145.479 [DAT](INFO): Got DATA 2
2021-11-17T18:02:25.480Z,1637172145.480 [DAT](INFO): DAT read: Source:001  Destination:007

2021-11-17T18:02:25.480Z,1637172145.480 [DAT](INFO): Got Src/Dest after DATA 
2021-11-17T18:02:25.480Z,1637172145.480 [DAT](INFO): DATA Src=1, Dst=7
2021-11-17T18:02:25.481Z,1637172145.481 [DAT](INFO): DAT read: CRC:Pass MPD:03.7 PSNR:12.0 AGC:88 SPD:-0.1 CCERR:010

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

2021-11-17T18:02:25.483Z,1637172145.483 [DAT](INFO): DAT read: <EOP>

2021-11-17T18:02:25.484Z,1637172145.484 [DAT](INFO): Sent 184 bytes from file Logs/20211117T175209/Courier0900.lzma.parts
2021-11-17T18:02:25.484Z,1637172145.484 [DAT](INFO): Packets left to send: 6
2021-11-17T18:02:25.485Z,1637172145.485 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-17T18:02:25.486Z,1637172145.486 [DAT](INFO): #Rx 27: Read direction message, but no range.
2021-11-17T18:02:25.487Z,1637172145.487 [DAT](INFO): direction in vehicle frame: [ -0.556277 forward, -0.815472 starboard, 0.159881 keelward ]
2021-11-17T18:02:26.762Z,1637172146.762 [DAT](INFO): #Outgoing data=1
2021-11-17T18:02:26.763Z,1637172146.763 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-17T18:02:26.878Z,1637172146.878 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-17T18:02:30.369Z,1637172150.369 [DAT](INFO): DAT read: Forwarding Delay UpTx time:18:01:53.2495

2021-11-17T18:02:30.370Z,1637172150.370 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-17T18:02:39.214Z,1637172159.214 [DAT](INFO): DAT read: Rx Time:18:02:01.6375

2021-11-17T18:02:39.214Z,1637172159.214 [DAT](INFO): received an acoustic signal
2021-11-17T18:02:40.898Z,1637172160.898 [DAT](INFO): DAT read: 18:02:01.6375 LVL= 32752, 32753, 32754, 32755, AGC= 88, IDX= 166, 0.36,-2.117,-2.049,-2.108,-2.078, PHS=-0.042, 0.074,-0.045, RAW= 331.0,   2.2, CAL= 331.3,  -0.0, ROT= 238.7,   0.0

2021-11-17T18:02:40.900Z,1637172160.900 [DAT](INFO): got valid direction response:
 18:02:01.6375 LVL= 32752, 32753, 32754, 32755, AGC= 88, IDX= 166, 0.36,-2.117,-2.049,-2.108,-2.078, PHS=-0.042, 0.074,-0.045, RAW= 331.0,   2.2, CAL= 331.3,  -0.0, ROT= 238.7,   0.0

2021-11-17T18:02:40.900Z,1637172160.900 [DAT](INFO): DAT read: 

2021-11-17T18:02:40.901Z,1637172160.901 [DAT](INFO): DAT read: DATA(0002):~~

2021-11-17T18:02:40.901Z,1637172160.901 [DAT](INFO): Got DATA 2
2021-11-17T18:02:40.902Z,1637172160.902 [DAT](INFO): DAT read: Source:001  Destination:007

2021-11-17T18:02:40.902Z,1637172160.902 [DAT](INFO): Got Src/Dest after DATA 
2021-11-17T18:02:40.902Z,1637172160.902 [DAT](INFO): DATA Src=1, Dst=7
2021-11-17T18:02:40.904Z,1637172160.904 [DAT](INFO): DAT read: CRC:Pass MPD:03.8 PSNR:11.7 AGC:89 SPD:+0.1 CCERR:010

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

2021-11-17T18:02:40.906Z,1637172160.906 [DAT](INFO): DAT read: <EOP>

2021-11-17T18:02:40.906Z,1637172160.906 [DAT](INFO): Sent 184 bytes from file Logs/20211117T175209/Courier0900.lzma.parts
2021-11-17T18:02:40.906Z,1637172160.906 [DAT](INFO): Packets left to send: 5
2021-11-17T18:02:40.908Z,1637172160.908 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-17T18:02:40.909Z,1637172160.909 [DAT](INFO): #Rx 28: Read direction message, but no range.
2021-11-17T18:02:40.910Z,1637172160.910 [DAT](INFO): direction in vehicle frame: [ -0.519519 forward, -0.854459 starboard, 0.000000 keelward ]
2021-11-17T18:02:41.691Z,1637172161.691 [DAT](INFO): #Outgoing data=1
2021-11-17T18:02:41.691Z,1637172161.691 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-17T18:02:41.777Z,1637172161.777 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-17T18:02:45.502Z,1637172165.502 [DAT](INFO): DAT read: Forwarding Delay UpTx time:18:02:08.1493

2021-11-17T18:02:45.503Z,1637172165.503 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-17T18:02:54.481Z,1637172174.481 [DAT](INFO): DAT read: Rx Time:18:02:16.5376

2021-11-17T18:02:54.481Z,1637172174.481 [DAT](INFO): received an acoustic signal
2021-11-17T18:02:55.446Z,1637172175.446 [DAT](INFO): DAT read: 18:02:16.5376 LVL= 32752, 32753, 32754, 32755, AGC= 90, IDX= 188,-0.27, 1.564, 1.614, 1.557, 1.555, PHS= 0.005, 0.103,-0.013, RAW= 338.3, -17.2, CAL= 339.7, -19.8, ROT= 230.3,  19.8

2021-11-17T18:02:55.448Z,1637172175.448 [DAT](INFO): got valid direction response:
 18:02:16.5376 LVL= 32752, 32753, 32754, 32755, AGC= 90, IDX= 188,-0.27, 1.564, 1.614, 1.557, 1.555, PHS= 0.005, 0.103,-0.013, RAW= 338.3, -17.2, CAL= 339.7, -19.8, ROT= 230.3,  19.8

2021-11-17T18:02:55.448Z,1637172175.448 [DAT](INFO): DAT read: 

2021-11-17T18:02:55.449Z,1637172175.449 [DAT](INFO): DAT read: DATA(0002):~~

2021-11-17T18:02:55.449Z,1637172175.449 [DAT](INFO): Got DATA 2
2021-11-17T18:02:55.450Z,1637172175.450 [DAT](INFO): DAT read: Source:001  Destination:007

2021-11-17T18:02:55.450Z,1637172175.450 [DAT](INFO): Got Src/Dest after DATA 
2021-11-17T18:02:55.450Z,1637172175.450 [DAT](INFO): DATA Src=1, Dst=7
2021-11-17T18:02:55.452Z,1637172175.452 [DAT](INFO): DAT read: CRC:Pass MPD:03.8 PSNR:12.7 AGC:89 SPD:-0.1 CCERR:010

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

2021-11-17T18:02:55.453Z,1637172175.453 [DAT](INFO): DAT read: <EOP>

2021-11-17T18:02:55.454Z,1637172175.454 [DAT](INFO): Sent 184 bytes from file Logs/20211117T175209/Courier0900.lzma.parts
2021-11-17T18:02:55.454Z,1637172175.454 [DAT](INFO): Packets left to send: 4
2021-11-17T18:02:55.508Z,1637172175.508 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-17T18:02:55.508Z,1637172175.508 [DAT](INFO): #Rx 29: Read direction message, but no range.
2021-11-17T18:02:55.509Z,1637172175.509 [DAT](INFO): direction in vehicle frame: [ -0.601004 forward, -0.723913 starboard, 0.338738 keelward ]
2021-11-17T18:02:56.693Z,1637172176.693 [DAT](INFO): #Outgoing data=1
2021-11-17T18:02:56.693Z,1637172176.693 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-17T18:02:57.550Z,1637172177.550 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-17T18:03:01.138Z,1637172181.138 [DAT](INFO): DAT read: Forwarding Delay UpTx time:18:02:23.8990

2021-11-17T18:03:01.138Z,1637172181.138 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-17T18:03:10.046Z,1637172190.046 [DAT](INFO): DAT read: Rx Time:18:02:32.2879

2021-11-17T18:03:10.046Z,1637172190.046 [DAT](INFO): received an acoustic signal
2021-11-17T18:03:10.867Z,1637172190.867 [DAT](INFO): DAT read: 18:02:32.2879 LVL= 32752, 32753, 32754, 32755, AGC= 90, IDX= 193, 0.40, 3.073, 3.121, 3.074, 3.066, PHS= 0.003, 0.100,-0.007, RAW= 334.7, -18.4, CAL= 336.4, -20.9, ROT= 233.6,  20.9

2021-11-17T18:03:10.868Z,1637172190.868 [DAT](INFO): got valid direction response:
 18:02:32.2879 LVL= 32752, 32753, 32754, 32755, AGC= 90, IDX= 193, 0.40, 3.073, 3.121, 3.074, 3.066, PHS= 0.003, 0.100,-0.007, RAW= 334.7, -18.4, CAL= 336.4, -20.9, ROT= 233.6,  20.9

2021-11-17T18:03:10.869Z,1637172190.869 [DAT](INFO): DAT read: 

2021-11-17T18:03:10.870Z,1637172190.870 [DAT](INFO): #Rx 30: Read direction message, but no range.
2021-11-17T18:03:10.871Z,1637172190.871 [DAT](INFO): direction in vehicle frame: [ -0.554374 forward, -0.751935 starboard, 0.356738 keelward ]
2021-11-17T18:03:11.264Z,1637172191.264 [DAT](INFO): DAT read: DATA(0002):~~

2021-11-17T18:03:11.264Z,1637172191.264 [DAT](INFO): Got DATA 2
2021-11-17T18:03:11.265Z,1637172191.265 [DAT](INFO): DAT read: Source:001  Destination:007

2021-11-17T18:03:11.265Z,1637172191.265 [DAT](INFO): Got Src/Dest after DATA 
2021-11-17T18:03:11.266Z,1637172191.266 [DAT](INFO): DATA Src=1, Dst=7
2021-11-17T18:03:11.268Z,1637172191.268 [DAT](INFO): DAT read: CRC:Pass MPD:03.8 PSNR:12.3 AGC:91 SPD:+0.0 CCERR:010

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

2021-11-17T18:03:11.269Z,1637172191.269 [DAT](INFO): DAT read: <EOP>

2021-11-17T18:03:11.270Z,1637172191.270 [DAT](INFO): Sent 184 bytes from file Logs/20211117T175209/Courier0900.lzma.parts
2021-11-17T18:03:11.270Z,1637172191.270 [DAT](INFO): Packets left to send: 3
2021-11-17T18:03:11.272Z,1637172191.272 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-17T18:03:12.142Z,1637172192.142 [DAT](INFO): #Outgoing data=1
2021-11-17T18:03:12.142Z,1637172192.142 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-17T18:03:12.229Z,1637172192.229 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-17T18:03:16.001Z,1637172196.001 [DAT](INFO): DAT read: Forwarding Delay UpTx time:18:02:38.5973

2021-11-17T18:03:16.001Z,1637172196.001 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-17T18:03:24.770Z,1637172204.770 [DAT](INFO): DAT read: Rx Time:18:02:46.9882

2021-11-17T18:03:24.770Z,1637172204.770 [DAT](INFO): received an acoustic signal
2021-11-17T18:03:25.603Z,1637172205.603 [DAT](INFO): DAT read: 18:02:46.9882 LVL= 32752, 32753, 32754, 32755, AGC= 87, IDX= 199,-0.21, 2.340, 2.429, 2.353, 2.402, PHS=-0.066, 0.072,-0.064, RAW= 329.2,   8.6, CAL= 329.3,   8.4, ROT= 240.7,  -8.4

2021-11-17T18:03:25.604Z,1637172205.604 [DAT](INFO): got valid direction response:
 18:02:46.9882 LVL= 32752, 32753, 32754, 32755, AGC= 87, IDX= 199,-0.21, 2.340, 2.429, 2.353, 2.402, PHS=-0.066, 0.072,-0.064, RAW= 329.2,   8.6, CAL= 329.3,   8.4, ROT= 240.7,  -8.4

2021-11-17T18:03:25.604Z,1637172205.604 [DAT](INFO): DAT read: 

2021-11-17T18:03:25.605Z,1637172205.605 [DAT](INFO): DAT read: DATA(0002):~~

2021-11-17T18:03:25.606Z,1637172205.606 [DAT](INFO): Got DATA 2
2021-11-17T18:03:25.606Z,1637172205.606 [DAT](INFO): DAT read: Source:001  Destination:007

2021-11-17T18:03:25.607Z,1637172205.607 [DAT](INFO): Got Src/Dest after DATA 
2021-11-17T18:03:25.607Z,1637172205.607 [DAT](INFO): DATA Src=1, Dst=7
2021-11-17T18:03:25.608Z,1637172205.608 [DAT](INFO): #Rx 31: Read direction message, but no range.
2021-11-17T18:03:25.609Z,1637172205.609 [DAT](INFO): direction in vehicle frame: [ -0.484133 forward, -0.862714 starboard, -0.146083 keelward ]
2021-11-17T18:03:26.493Z,1637172206.493 [DAT](INFO): DAT read: CRC:Pass MPD:03.8 PSNR:11.5 AGC:89 SPD:+0.1 CCERR:009

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

2021-11-17T18:03:26.495Z,1637172206.495 [DAT](INFO): DAT read: <EOP>

2021-11-17T18:03:26.496Z,1637172206.496 [DAT](INFO): Sent 184 bytes from file Logs/20211117T175209/Courier0900.lzma.parts
2021-11-17T18:03:26.496Z,1637172206.496 [DAT](INFO): Packets left to send: 2
2021-11-17T18:03:26.497Z,1637172206.497 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-17T18:03:27.144Z,1637172207.144 [DAT](INFO): #Outgoing data=1
2021-11-17T18:03:27.144Z,1637172207.144 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-17T18:03:27.233Z,1637172207.233 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-17T18:03:30.931Z,1637172210.931 [DAT](INFO): DAT read: Forwarding Delay UpTx time:18:02:53.5971

2021-11-17T18:03:30.931Z,1637172210.931 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-17T18:03:39.802Z,1637172219.802 [DAT](INFO): DAT read: Rx Time:18:03:01.9884

2021-11-17T18:03:39.802Z,1637172219.802 [DAT](INFO): received an acoustic signal
2021-11-17T18:03:40.627Z,1637172220.627 [DAT](INFO): DAT read: 18:03:01.9883 LVL= 32752, 32753, 32754, 32755, AGC= 89, IDX= 188, 0.14,-2.848,-2.794,-2.849,-2.836, PHS=-0.016, 0.086,-0.028, RAW= 335.3,  -7.7, CAL= 336.3, -10.1, ROT= 233.7,  10.1

2021-11-17T18:03:40.628Z,1637172220.628 [DAT](INFO): got valid direction response:
 18:03:01.9883 LVL= 32752, 32753, 32754, 32755, AGC= 89, IDX= 188, 0.14,-2.848,-2.794,-2.849,-2.836, PHS=-0.016, 0.086,-0.028, RAW= 335.3,  -7.7, CAL= 336.3, -10.1, ROT= 233.7,  10.1

2021-11-17T18:03:40.629Z,1637172220.629 [DAT](INFO): DAT read: 

2021-11-17T18:03:40.630Z,1637172220.630 [DAT](INFO): DAT read: DATA(0002):~~

2021-11-17T18:03:40.630Z,1637172220.630 [DAT](INFO): Got DATA 2
2021-11-17T18:03:40.631Z,1637172220.631 [DAT](INFO): DAT read: Source:001  Destination:007

2021-11-17T18:03:40.631Z,1637172220.631 [DAT](INFO): Got Src/Dest after DATA 
2021-11-17T18:03:40.632Z,1637172220.632 [DAT](INFO): DATA Src=1, Dst=7
2021-11-17T18:03:40.632Z,1637172220.632 [DAT](INFO): #Rx 32: Read direction message, but no range.
2021-11-17T18:03:40.634Z,1637172220.634 [DAT](INFO): direction in vehicle frame: [ -0.582839 forward, -0.793439 starboard, 0.175367 keelward ]
2021-11-17T18:03:41.517Z,1637172221.517 [DAT](INFO): DAT read: CRC:Pass MPD:03.9 PSNR:11.4 AGC:91 SPD:+0.1 CCERR:009

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

2021-11-17T18:03:41.519Z,1637172221.519 [DAT](INFO): DAT read: <EOP>

2021-11-17T18:03:41.520Z,1637172221.520 [DAT](INFO): Sent 184 bytes from file Logs/20211117T175209/Courier0900.lzma.parts
2021-11-17T18:03:41.520Z,1637172221.520 [DAT](INFO): Packets left to send: 1
2021-11-17T18:03:41.521Z,1637172221.521 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-17T18:03:42.142Z,1637172222.142 [DAT](INFO): #Outgoing data=1
2021-11-17T18:03:42.143Z,1637172222.143 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-17T18:03:42.230Z,1637172222.230 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-17T18:03:45.918Z,1637172225.918 [DAT](INFO): DAT read: Forwarding Delay UpTx time:18:03:08.5468

2021-11-17T18:03:45.918Z,1637172225.918 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-17T18:03:54.365Z,1637172234.365 [DAT](INFO): DAT read: Rx Time:18:03:16.2887

2021-11-17T18:03:54.365Z,1637172234.365 [DAT](INFO): received an acoustic signal
2021-11-17T18:03:55.253Z,1637172235.253 [DAT](INFO): DAT read: 18:03:16.2887 LVL= 32752, 32753, 32754, 32755, AGC= 90, IDX= 193, 0.49, 3.073, 3.121, 3.068, 3.066, PHS= 0.003, 0.099,-0.013, RAW= 337.5, -16.6, CAL= 338.9, -19.1, ROT= 231.1,  19.1

2021-11-17T18:03:55.254Z,1637172235.254 [DAT](INFO): got valid direction response:
 18:03:16.2887 LVL= 32752, 32753, 32754, 32755, AGC= 90, IDX= 193, 0.49, 3.073, 3.121, 3.068, 3.066, PHS= 0.003, 0.099,-0.013, RAW= 337.5, -16.6, CAL= 338.9, -19.1, ROT= 231.1,  19.1

2021-11-17T18:03:55.255Z,1637172235.255 [DAT](INFO): DAT read: 

2021-11-17T18:03:55.256Z,1637172235.256 [DAT](INFO): DAT read: DATA(0002):~~

2021-11-17T18:03:55.256Z,1637172235.256 [DAT](INFO): Got DATA 2
2021-11-17T18:03:55.257Z,1637172235.257 [DAT](INFO): DAT read: Source:001  Destination:007

2021-11-17T18:03:55.257Z,1637172235.257 [DAT](INFO): Got Src/Dest after DATA 
2021-11-17T18:03:55.257Z,1637172235.257 [DAT](INFO): DATA Src=1, Dst=7
2021-11-17T18:03:55.259Z,1637172235.259 [DAT](INFO): DAT read: CRC:Pass MPD:03.7 PSNR:12.1 AGC:90 SPD:+0.0 CCERR:010

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

2021-11-17T18:03:55.260Z,1637172235.260 [DAT](INFO): DAT read: <EOP>

2021-11-17T18:03:55.261Z,1637172235.261 [DAT](INFO): Sent 124 bytes from file Logs/20211117T175209/Courier0900.lzma.parts
2021-11-17T18:03:55.261Z,1637172235.261 [DAT](INFO): Packets left to send: 0
2021-11-17T18:03:55.263Z,1637172235.263 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-17T18:03:55.264Z,1637172235.264 [DAT](INFO): #Rx 33: Read direction message, but no range.
2021-11-17T18:03:55.265Z,1637172235.265 [DAT](INFO): direction in vehicle frame: [ -0.593393 forward, -0.735400 starboard, 0.327218 keelward ]
2021-11-17T18:03:56.203Z,1637172236.203 [Default:CheckIn:Read_Iridium] Stopped
2021-11-17T18:03:56.203Z,1637172236.203 [Default:CheckIn:C.Wait] Running Loop=1
2021-11-17T18:03:56.203Z,1637172236.203 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-11-17T18:04:10.876Z,1637172250.876 [CommandExec](IMPORTANT): got command failComponent
2021-11-17T18:04:10.877Z,1637172250.877 [CommandExec](IMPORTANT): Failed components:
2021-11-17T18:04:10.877Z,1637172250.877 [CommandExec](IMPORTANT): DropWeight: Hardware Fault
2021-11-17T18:04:14.513Z,1637172254.513 [CommandExec](IMPORTANT): got command failComponent none DropWeight
2021-11-17T18:04:14.513Z,1637172254.513 [DropWeight] No Fault, FailCount= 1
2021-11-17T18:04:14.513Z,1637172254.513 [CommandExec](IMPORTANT): DropWeight failureMode is No Fault
2021-11-17T18:04:20.406Z,1637172260.406 [CommandExec](IMPORTANT): got command failComponent hardware DropWeight
2021-11-17T18:04:20.406Z,1637172260.406 [DropWeight] Hardware Fault, FailCount= 2
2021-11-17T18:04:20.406Z,1637172260.406 [DropWeight](ERROR): Hardware Fault
2021-11-17T18:04:20.407Z,1637172260.407 [CommandExec](IMPORTANT): DropWeight failureMode is Hardware Fault
2021-11-17T18:04:20.686Z,1637172260.686 [CBIT](ERROR): Hardware Fault in component: DropWeight
2021-11-17T18:04:20.686Z,1637172260.686 [CBIT](CRITICAL): Hardware Fault in component: DropWeight
2021-11-17T18:04:21.097Z,1637172261.097 [CBIT](INFO): Critical error at 20211117T180420
2021-11-17T18:04:29.544Z,1637172269.544 [NAL9602](INFO): Not Powering down - fast GPS
2021-11-17T18:04:53.103Z,1637172293.103 [CommandExec](IMPORTANT): got command failComponent
2021-11-17T18:04:53.103Z,1637172293.103 [CommandExec](IMPORTANT): Failed components:
2021-11-17T18:04:53.103Z,1637172293.103 [CommandExec](IMPORTANT): DropWeight: Hardware Fault
2021-11-17T18:04:55.691Z,1637172295.691 [CommandExec](IMPORTANT): got command failComponent none DropWeight
2021-11-17T18:04:55.692Z,1637172295.692 [DropWeight] No Fault, FailCount= 2
2021-11-17T18:04:55.692Z,1637172295.692 [CommandExec](IMPORTANT): DropWeight failureMode is No Fault
2021-11-17T18:04:56.613Z,1637172296.613 [DropWeight](CRITICAL): DROP WEIGHT MISSING.

2021-11-17T18:04:56.613Z,1637172296.613 [DropWeight] Hardware Fault, FailCount= 3
2021-11-17T18:04:56.613Z,1637172296.613 [DropWeight](ERROR): Hardware Fault
2021-11-17T18:04:56.629Z,1637172296.629 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2021-11-17T18:04:56.629Z,1637172296.629 [Default:CheckIn:C.Wait] Stopped
2021-11-17T18:04:56.629Z,1637172296.629 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-11-17T18:04:56.629Z,1637172296.629 [Default:CheckIn:D] Running Loop=1
2021-11-17T18:04:56.674Z,1637172296.674 [CBIT](INFO): Critical error at 20211117T180456
2021-11-17T18:04:56.676Z,1637172296.676 [CBIT](ERROR): Hardware Fault in component: DropWeight
2021-11-17T18:04:56.677Z,1637172296.677 [CBIT](CRITICAL): Hardware Fault in component: DropWeight
2021-11-17T18:04:57.045Z,1637172297.045 [Default:CheckIn:D] Stopped
2021-11-17T18:04:57.045Z,1637172297.045 [Default:CheckIn:E] Running Loop=1
2021-11-17T18:04:57.052Z,1637172297.052 [CBIT](INFO): Critical error at 20211117T180456
2021-11-17T18:04:57.454Z,1637172297.454 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 9.276653 min 
2021-11-17T18:04:57.454Z,1637172297.454 [Default:CheckIn:E] Stopped
2021-11-17T18:04:57.454Z,1637172297.454 [Default:CheckIn](INFO): Completed Default:CheckIn
2021-11-17T18:04:57.454Z,1637172297.454 [Default:CheckIn] Stopped
2021-11-17T18:04:57.454Z,1637172297.454 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-11-17T18:04:57.455Z,1637172297.455 [Default:CheckIn](INFO): Running loop #2
2021-11-17T18:04:57.455Z,1637172297.455 [Default:CheckIn] Running Loop=2
2021-11-17T18:04:57.455Z,1637172297.455 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-11-17T18:04:57.455Z,1637172297.455 [Default:CheckIn:Read_GPS] Running Loop=1
2021-11-17T18:04:59.036Z,1637172299.036 [NAL9602](FAULT): GPS failed to acquire within timeout.
2021-11-17T18:04:59.036Z,1637172299.036 [NAL9602] Data Fault, FailCount= 1
2021-11-17T18:04:59.036Z,1637172299.036 [NAL9602](ERROR): Data Fault
2021-11-17T18:04:59.087Z,1637172299.087 [CBIT](ERROR): Data Fault in component: NAL9602
2021-11-17T18:04:59.457Z,1637172299.457 [NAL9602](INFO): Powering down
2021-11-17T18:05:00.283Z,1637172300.283 [CBIT](INFO): Clearing failed state for component NAL9602
2021-11-17T18:05:00.283Z,1637172300.283 [NAL9602] No Fault, FailCount= 1
2021-11-17T18:05:16.492Z,1637172316.492 [CommandExec](IMPORTANT): got command set NAL9602.time_fix 1637172352.000000 second
2021-11-17T18:05:29.740Z,1637172329.740 [NAL9602](INFO): Powering up NAL9602
2021-11-17T18:05:40.657Z,1637172340.657 [NAL9602](INFO): NAL9602 initialized
2021-11-17T18:05:52.934Z,1637172352.934 [CommandExec](IMPORTANT): got command set NAL9602.time_fix 1637172352.000000 second
2021-11-17T18:05:53.190Z,1637172353.190 [Default:CheckIn:Read_GPS] Stopped
2021-11-17T18:05:53.190Z,1637172353.190 [Default:CheckIn:Read_Iridium] Running Loop=1
2021-11-17T18:05:54.564Z,1637172354.564 [DAT](INFO): #Outgoing data=1
2021-11-17T18:05:54.564Z,1637172354.564 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-17T18:05:54.669Z,1637172354.669 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-17T18:05:58.242Z,1637172358.242 [DAT](INFO): DAT read: Forwarding Delay UpTx time:18:05:21.0444

2021-11-17T18:05:58.243Z,1637172358.243 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-17T18:06:07.126Z,1637172367.126 [DAT](INFO): DAT read: Rx Time:18:05:29.4414

2021-11-17T18:06:07.126Z,1637172367.126 [DAT](INFO): received an acoustic signal
2021-11-17T18:06:08.395Z,1637172368.395 [DAT](INFO): DAT read: 18:05:29.4413 LVL= 32752, 32753, 32754, 32755, AGC= 88, IDX= 229,-0.28, 1.459, 1.517, 1.459, 1.471, PHS=-0.015, 0.090,-0.027, RAW= 335.3,  -8.6, CAL= 336.4, -11.1, ROT= 233.6,  11.1

2021-11-17T18:06:08.420Z,1637172368.420 [DAT](INFO): got valid direction response:
 18:05:29.4413 LVL= 32752, 32753, 32754, 32755, AGC= 88, IDX= 229,-0.28, 1.459, 1.517, 1.459, 1.471, PHS=-0.015, 0.090,-0.027, RAW= 335.3,  -8.6, CAL= 336.4, -11.1, ROT= 233.6,  11.1

2021-11-17T18:06:08.420Z,1637172368.420 [DAT](INFO): DAT read: 

2021-11-17T18:06:08.421Z,1637172368.421 [DAT](INFO): DAT read: DATA(0002):~~

2021-11-17T18:06:08.421Z,1637172368.421 [DAT](INFO): Got DATA 2
2021-11-17T18:06:08.422Z,1637172368.422 [DAT](INFO): DAT read: Source:001  Destination:007

2021-11-17T18:06:08.422Z,1637172368.422 [DAT](INFO): Got Src/Dest after DATA 
2021-11-17T18:06:08.423Z,1637172368.423 [DAT](INFO): DATA Src=1, Dst=7
2021-11-17T18:06:08.426Z,1637172368.426 [DAT](INFO): DAT read: CRC:Pass MPD:03.7 PSNR:12.3 AGC:86 SPD:+0.0 CCERR:010

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

2021-11-17T18:06:08.430Z,1637172368.430 [DAT](INFO): DAT read: <EOP>

2021-11-17T18:06:08.432Z,1637172368.432 [DAT](INFO): Sent 184 bytes from file Logs/20211117T175209/Courier0007.lzma.parts
2021-11-17T18:06:08.432Z,1637172368.432 [DAT](INFO): Packets left to send: 1
2021-11-17T18:06:08.598Z,1637172368.598 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-17T18:06:08.599Z,1637172368.599 [DAT](INFO): #Rx 34: Read direction message, but no range.
2021-11-17T18:06:08.601Z,1637172368.601 [DAT](INFO): direction in vehicle frame: [ -0.582317 forward, -0.789836 starboard, 0.192522 keelward ]
2021-11-17T18:06:09.303Z,1637172369.303 [DAT](INFO): #Outgoing data=1
2021-11-17T18:06:09.303Z,1637172369.303 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2021-11-17T18:06:09.387Z,1637172369.387 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2021-11-17T18:06:13.002Z,1637172373.002 [DAT](INFO): DAT read: Forwarding Delay UpTx time:18:05:35.6442

2021-11-17T18:06:13.003Z,1637172373.003 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2021-11-17T18:06:20.693Z,1637172380.693 [DAT](INFO): DAT read: Rx Time:18:05:42.7916

2021-11-17T18:06:20.693Z,1637172380.693 [DAT](INFO): received an acoustic signal
2021-11-17T18:06:21.503Z,1637172381.503 [DAT](INFO): DAT read: 18:05:42.7916 LVL= 32752, 32753, 32754, 32755, AGC= 86, IDX= 442,-0.46, 2.241, 2.311, 2.252, 2.276, PHS=-0.039, 0.079,-0.039, RAW= 330.1,  -0.2, CAL= 330.6,  -2.5, ROT= 239.4,   2.5

2021-11-17T18:06:21.504Z,1637172381.504 [DAT](INFO): got valid direction response:
 18:05:42.7916 LVL= 32752, 32753, 32754, 32755, AGC= 86, IDX= 442,-0.46, 2.241, 2.311, 2.252, 2.276, PHS=-0.039, 0.079,-0.039, RAW= 330.1,  -0.2, CAL= 330.6,  -2.5, ROT= 239.4,   2.5

2021-11-17T18:06:21.504Z,1637172381.504 [DAT](INFO): DAT read: 

2021-11-17T18:06:21.505Z,1637172381.505 [DAT](INFO): DAT read: DATA(0002):~~

2021-11-17T18:06:21.505Z,1637172381.505 [DAT](INFO): Got DATA 2
2021-11-17T18:06:21.506Z,1637172381.506 [DAT](INFO): DAT read: Source:001  Destination:007

2021-11-17T18:06:21.506Z,1637172381.506 [DAT](INFO): Got Src/Dest after DATA 
2021-11-17T18:06:21.507Z,1637172381.507 [DAT](INFO): DATA Src=1, Dst=7
2021-11-17T18:06:21.604Z,1637172381.604 [DAT](INFO): DAT read: CRC:Pass MPD:03.8 PSNR:12.5 AGC:90 SPD:+0.0 CCERR:010

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

2021-11-17T18:06:21.606Z,1637172381.606 [DAT](INFO): DAT read: <EOP>

2021-11-17T18:06:21.606Z,1637172381.606 [DAT](INFO): Sent 71 bytes from file Logs/20211117T175209/Courier0007.lzma.parts
2021-11-17T18:06:21.606Z,1637172381.606 [DAT](INFO): Packets left to send: 0
2021-11-17T18:06:21.625Z,1637172381.625 [DAT](DEBUG): In sendingVerified, sbd waiting so set commsState_ = SENDING_FILL_BUFFER
2021-11-17T18:06:21.625Z,1637172381.625 [DAT](INFO): #Rx 35: Read direction message, but no range.
2021-11-17T18:06:21.626Z,1637172381.626 [DAT](INFO): direction in vehicle frame: [ -0.508557 forward, -0.859923 starboard, 0.043619 keelward ]
2021-11-17T18:06:22.782Z,1637172382.782 [Default:CheckIn:Read_Iridium] Stopped
2021-11-17T18:06:22.782Z,1637172382.782 [Default:CheckIn:C.Wait] Running Loop=1
2021-11-17T18:06:22.782Z,1637172382.782 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2021-11-17T18:06:45.117Z,1637172405.117 [CommandExec](IMPORTANT): got command restart application
2021-11-17T18:06:46.120Z,1637172406.120 [CommandExec ThreadHandler](INFO): Uninitializing protected caller thread.
2021-11-17T18:06:46.120Z,1637172406.120 [CommandExec](INFO): Uninitializing the command executive.
2021-11-17T18:06:46.120Z,1637172406.120 [CommandExec](INFO): Uninitializing the command scheduler.
2021-11-17T18:06:46.120Z,1637172406.120 [CommandExec ThreadHandler](INFO): Thread cancelled.
2021-11-17T18:06:46.179Z,1637172406.179 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2021-11-17T18:06:46.179Z,1637172406.179 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2021-11-17T18:06:46.180Z,1637172406.180 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2021-11-17T18:06:46.180Z,1637172406.180 [NavChartDb](INFO): Join timeout helper Thread ID is 7549
2021-11-17T18:06:46.227Z,1637172406.227 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2021-11-17T18:06:46.228Z,1637172406.228 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2021-11-17T18:06:46.244Z,1637172406.244 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2021-11-17T18:06:46.244Z,1637172406.244 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2021-11-17T18:06:46.244Z,1637172406.244 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 7550
2021-11-17T18:06:46.245Z,1637172406.245 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread.
2021-11-17T18:06:46.245Z,1637172406.245 [WetLabsBB2FL](INFO): Powering down
2021-11-17T18:06:46.246Z,1637172406.246 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2021-11-17T18:06:46.246Z,1637172406.246 [ComponentRegistry](INFO): Shutting down CTD_Seabird ThreadHandler
2021-11-17T18:06:46.246Z,1637172406.246 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2021-11-17T18:06:46.246Z,1637172406.246 [CTD_Seabird](INFO): Join timeout helper Thread ID is 7551
2021-11-17T18:06:46.684Z,1637172406.684 [CTD_Seabird](INFO): Powering down
2021-11-17T18:06:46.696Z,1637172406.696 [CTD_Seabird ThreadHandler](INFO): Uninitializing protected caller thread.
2021-11-17T18:06:46.696Z,1637172406.696 [CTD_Seabird](INFO): Powering down
2021-11-17T18:06:46.713Z,1637172406.713 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2021-11-17T18:06:46.724Z,1637172406.724 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2021-11-17T18:06:46.724Z,1637172406.724 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2021-11-17T18:06:46.724Z,1637172406.724 [Radio_Surface](INFO): Join timeout helper Thread ID is 7555
2021-11-17T18:06:47.040Z,1637172407.040 [Radio_Surface](INFO): Powering down
2021-11-17T18:06:47.040Z,1637172407.040 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2021-11-17T18:06:47.041Z,1637172407.041 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2021-11-17T18:06:47.051Z,1637172407.051 [ComponentRegistry](INFO): Shutting down Onboard ThreadHandler
2021-11-17T18:06:47.052Z,1637172407.052 [Onboard ThreadHandler](INFO): Thread cancelled.
2021-11-17T18:06:47.052Z,1637172407.052 [Onboard](INFO): Join timeout helper Thread ID is 7556
2021-11-17T18:06:51.572Z,1637172411.572 [Onboard ThreadHandler](INFO): Uninitializing protected caller thread.
2021-11-17T18:06:51.572Z,1637172411.572 [Onboard ThreadHandler](INFO): Thread cancelled.
2021-11-17T18:06:51.588Z,1637172411.588 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2021-11-17T18:06:51.588Z,1637172411.588 [logger ThreadHandler](INFO): Thread cancelled.
2021-11-17T18:06:51.589Z,1637172411.589 [logger](INFO): Join timeout helper Thread ID is 7557
2021-11-17T18:06:51.626Z,1637172411.626 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2021-11-17T18:06:51.626Z,1637172411.626 [logger ThreadHandler](INFO): Thread cancelled.
2021-11-17T18:06:51.636Z,1637172411.636 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2021-11-17T18:06:51.636Z,1637172411.636 [CommandLine ThreadHandler](INFO): Thread cancelled.
2021-11-17T18:06:51.637Z,1637172411.637 [CommandLine](INFO): Join timeout helper Thread ID is 7558
2021-11-17T18:06:51.660Z,1637172411.660 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2021-11-17T18:06:51.660Z,1637172411.660 [CommandLine ThreadHandler](INFO): Thread cancelled.
2021-11-17T18:06:51.661Z,1637172411.661 [ComponentRegistry](INFO): Shutting down CommandExec ThreadHandler
2021-11-17T18:06:51.661Z,1637172411.661 [CommandExec ThreadHandler](INFO): Thread cancelled.
2021-11-17T18:06:51.662Z,1637172411.662 [CommandExec](INFO): Join timeout helper Thread ID is 7559
2021-11-17T18:06:51.663Z,1637172411.663 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2021-11-17T18:06:51.663Z,1637172411.663 [controlThread ThreadHandler](INFO): Thread cancelled.
2021-11-17T18:06:51.664Z,1637172411.664 [controlThread](INFO): Join timeout helper Thread ID is 7560
2021-11-17T18:06:51.670Z,1637172411.670 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2021-11-17T18:06:51.670Z,1637172411.670 [controlThread](DEBUG): Uninitializing ControlThread
2021-11-17T18:06:51.670Z,1637172411.670 [AHRS_M2](INFO): Powering down
2021-11-17T18:06:51.740Z,1637172411.740 [NAL9602](INFO): Powering down
2021-11-17T18:06:51.742Z,1637172411.742 [DAT](INFO): Powering down
2021-11-17T18:06:51.862Z,1637172411.862 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2021-11-17T18:06:51.863Z,1637172411.863 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2021-11-17T18:06:51.863Z,1637172411.863 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2021-11-17T18:06:51.864Z,1637172411.864 [MissionManager](INFO): Uninitializing Mission Default
2021-11-17T18:06:51.864Z,1637172411.864 [Default] Stopped
2021-11-17T18:06:51.864Z,1637172411.864 [Default](DEBUG): Aggregate::uninitialize Default
2021-11-17T18:06:51.864Z,1637172411.864 [Default:B.GoToSurface] Stopped
2021-11-17T18:06:51.864Z,1637172411.864 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2021-11-17T18:06:51.864Z,1637172411.864 [Default:CheckIn] Stopped
2021-11-17T18:06:51.864Z,1637172411.864 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-11-17T18:06:51.865Z,1637172411.865 [Default:CheckIn:C.Wait] Stopped
2021-11-17T18:06:51.865Z,1637172411.865 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2021-11-17T18:06:51.868Z,1637172411.868 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2021-11-17T18:06:51.868Z,1637172411.868 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2021-11-17T18:06:51.869Z,1637172411.869 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2021-11-17T18:06:51.869Z,1637172411.869 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2021-11-17T18:06:51.869Z,1637172411.869 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2021-11-17T18:06:51.869Z,1637172411.869 [BuoyancyServo](INFO): Powering down
2021-11-17T18:06:51.884Z,1637172411.884 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2021-11-17T18:06:51.884Z,1637172411.884 [ElevatorServo](INFO): Powering down
2021-11-17T18:06:51.885Z,1637172411.885 [MassServo](DEBUG): Uninitialize Mass Servo.
2021-11-17T18:06:51.885Z,1637172411.885 [MassServo](INFO): Powering down
2021-11-17T18:06:51.886Z,1637172411.886 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2021-11-17T18:06:51.886Z,1637172411.886 [RudderServo](INFO): Powering down
2021-11-17T18:06:51.887Z,1637172411.887 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2021-11-17T18:06:51.887Z,1637172411.887 [ThrusterServo](INFO): Powering down
2021-11-17T18:06:51.888Z,1637172411.888 [SBIT](DEBUG): Uninitialize SBIT Component.
2021-11-17T18:06:51.888Z,1637172411.888 [IBIT](DEBUG): Uninitialize IBIT Component.
2021-11-17T18:06:51.889Z,1637172411.889 [CBIT](DEBUG): Uninitialize CBIT Component.
2021-11-17T18:06:51.889Z,1637172411.889 [CBIT](DEBUG): Powering off loads.
2021-11-17T18:06:51.899Z,1637172411.899 [CBIT](DEBUG): Disabling WDT.
2021-11-17T18:06:51.912Z,1637172411.912 [CBIT](DEBUG): Opening all GF detection circuits.
2021-11-17T18:06:51.913Z,1637172411.913 [controlThread ThreadHandler](INFO): Thread cancelled.
2021-11-17T18:06:51.975Z,1637172411.975 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2021-11-17T18:06:51.978Z,1637172411.978 [Onboard ThreadHandler](INFO): Thread cancelled.
2021-11-17T18:06:52.088Z,1637172412.088 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2021-11-17T18:06:52.092Z,1637172412.092 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2021-11-17T18:06:52.148Z,1637172412.148 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2021-11-17T18:06:52.251Z,1637172412.251 [logger ThreadHandler](INFO): Thread cancelled.