2021-05-18T04:20:51.969Z,1621311651.969 [Supervisor](DEBUG): Initializing supervisor.
2021-05-18T04:20:51.974Z,1621311651.974 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2021-05-18T04:20:51.974Z,1621311651.974 [SyncHandler](INFO): Protected caller Thread ID is 4781
2021-05-18T04:20:51.975Z,1621311651.975 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2021-05-18T04:20:51.976Z,1621311651.976 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2021-05-18T04:20:51.976Z,1621311651.976 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 4782
2021-05-18T04:20:51.980Z,1621311651.980 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2021-05-18T04:20:51.999Z,1621311651.999 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2021-05-18T04:20:52.000Z,1621311652.000 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2021-05-18T04:20:52.000Z,1621311652.000 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 4783
2021-05-18T04:20:52.002Z,1621311652.002 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2021-05-18T04:20:52.003Z,1621311652.003 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2021-05-18T04:20:52.004Z,1621311652.004 [logger ThreadHandler](INFO): Protected caller Thread ID is 4784
2021-05-18T04:20:52.008Z,1621311652.008 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2021-05-18T04:20:52.008Z,1621311652.008 [Supervisor](INFO): Looking for Config files in directory: Config/
2021-05-18T04:20:52.010Z,1621311652.010 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2021-05-18T04:20:52.247Z,1621311652.247 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2021-05-18T04:20:52.248Z,1621311652.248 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2021-05-18T04:20:52.327Z,1621311652.327 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2021-05-18T04:20:52.839Z,1621311652.839 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2021-05-18T04:20:52.840Z,1621311652.840 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2021-05-18T04:20:53.179Z,1621311653.179 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2021-05-18T04:20:53.180Z,1621311653.180 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2021-05-18T04:20:53.277Z,1621311653.277 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2021-05-18T04:20:53.277Z,1621311653.277 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2021-05-18T04:20:53.653Z,1621311653.653 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2021-05-18T04:20:53.653Z,1621311653.653 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2021-05-18T04:20:53.926Z,1621311653.926 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2021-05-18T04:20:53.927Z,1621311653.927 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2021-05-18T04:20:54.374Z,1621311654.374 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2021-05-18T04:20:54.375Z,1621311654.375 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2021-05-18T04:20:54.501Z,1621311654.501 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2021-05-18T04:20:54.502Z,1621311654.502 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2021-05-18T04:20:54.580Z,1621311654.580 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2021-05-18T04:20:55.275Z,1621311655.275 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2021-05-18T04:20:55.276Z,1621311655.276 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2021-05-18T04:20:55.644Z,1621311655.644 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2021-05-18T04:20:55.644Z,1621311655.644 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2021-05-18T04:20:55.841Z,1621311655.841 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2021-05-18T04:20:55.842Z,1621311655.842 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2021-05-18T04:20:55.944Z,1621311655.944 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2021-05-18T04:20:55.945Z,1621311655.945 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2021-05-18T04:20:56.096Z,1621311656.096 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2021-05-18T04:20:56.097Z,1621311656.097 [Supervisor](INFO): Opening Config file at: Config/Dock.cfg
2021-05-18T04:20:56.324Z,1621311656.324 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Dock
2021-05-18T04:20:56.326Z,1621311656.326 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2021-05-18T04:20:56.327Z,1621311656.327 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg
2021-05-18T04:20:56.418Z,1621311656.418 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2021-05-18T04:20:56.504Z,1621311656.504 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2021-05-18T04:20:56.870Z,1621311656.870 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg
2021-05-18T04:20:57.037Z,1621311657.037 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2021-05-18T04:20:57.134Z,1621311657.134 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2021-05-18T04:20:57.421Z,1621311657.421 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2021-05-18T04:20:57.642Z,1621311657.642 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg
2021-05-18T04:20:57.720Z,1621311657.720 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2021-05-18T04:20:57.892Z,1621311657.892 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2021-05-18T04:20:58.192Z,1621311658.192 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2021-05-18T04:20:58.490Z,1621311658.490 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Battery.cfg
2021-05-18T04:20:58.899Z,1621311658.899 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2021-05-18T04:20:58.942Z,1621311658.942 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/root/
2021-05-18T04:20:58.942Z,1621311658.942 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2021-05-18T04:20:58.948Z,1621311658.948 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2021-05-18T04:20:59.001Z,1621311659.001 [VerticalControl](DEBUG): Construct VerticalControl.
2021-05-18T04:20:59.061Z,1621311659.061 [VerticalControl] Loaded
2021-05-18T04:20:59.061Z,1621311659.061 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2021-05-18T04:20:59.063Z,1621311659.063 [HorizontalControl](DEBUG): Construct HorizontalControl.
2021-05-18T04:20:59.101Z,1621311659.101 [HorizontalControl] Loaded
2021-05-18T04:20:59.101Z,1621311659.101 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2021-05-18T04:20:59.104Z,1621311659.104 [SpeedControl](DEBUG): Construct SpeedControl.
2021-05-18T04:20:59.107Z,1621311659.107 [SpeedControl] Loaded
2021-05-18T04:20:59.107Z,1621311659.107 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2021-05-18T04:20:59.110Z,1621311659.110 [LoopControl](DEBUG): Construct LoopControl.
2021-05-18T04:20:59.110Z,1621311659.110 [LoopControl] Loaded
2021-05-18T04:20:59.110Z,1621311659.110 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2021-05-18T04:20:59.111Z,1621311659.111 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2021-05-18T04:20:59.111Z,1621311659.111 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2021-05-18T04:20:59.122Z,1621311659.122 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2021-05-18T04:20:59.123Z,1621311659.123 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2021-05-18T04:20:59.221Z,1621311659.221 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2021-05-18T04:20:59.222Z,1621311659.222 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2021-05-18T04:20:59.331Z,1621311659.331 [BuoyancyServo] Loaded
2021-05-18T04:20:59.332Z,1621311659.332 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2021-05-18T04:20:59.350Z,1621311659.350 [ElevatorServo] Loaded
2021-05-18T04:20:59.351Z,1621311659.351 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2021-05-18T04:20:59.368Z,1621311659.368 [MassServo] Loaded
2021-05-18T04:20:59.369Z,1621311659.369 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2021-05-18T04:20:59.386Z,1621311659.386 [RudderServo] Loaded
2021-05-18T04:20:59.386Z,1621311659.386 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2021-05-18T04:20:59.404Z,1621311659.404 [ThrusterServo] Loaded
2021-05-18T04:20:59.404Z,1621311659.404 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2021-05-18T04:20:59.404Z,1621311659.404 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2021-05-18T04:20:59.405Z,1621311659.405 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2021-05-18T04:20:59.483Z,1621311659.483 [DeadReckonUsingMultipleVelocitySources] Loaded
2021-05-18T04:20:59.484Z,1621311659.484 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2021-05-18T04:20:59.496Z,1621311659.496 [NavChart] Loaded
2021-05-18T04:20:59.496Z,1621311659.496 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2021-05-18T04:20:59.502Z,1621311659.502 [UniversalFixResidualReporter] Loaded
2021-05-18T04:20:59.502Z,1621311659.502 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2021-05-18T04:20:59.503Z,1621311659.503 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2021-05-18T04:20:59.503Z,1621311659.503 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2021-05-18T04:20:59.558Z,1621311659.558 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2021-05-18T04:20:59.558Z,1621311659.558 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2021-05-18T04:20:59.923Z,1621311659.923 [AHRS_M2] Loaded
2021-05-18T04:20:59.923Z,1621311659.923 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2021-05-18T04:21:00.699Z,1621311660.699 [BPC1] Loaded
2021-05-18T04:21:00.699Z,1621311660.699 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2021-05-18T04:21:00.772Z,1621311660.772 [DataOverHttps] Loaded
2021-05-18T04:21:00.772Z,1621311660.772 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2021-05-18T04:21:00.773Z,1621311660.773 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4087D4E0
2021-05-18T04:21:00.774Z,1621311660.774 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 4870
2021-05-18T04:21:00.793Z,1621311660.793 [Depth_Keller] Loaded
2021-05-18T04:21:00.793Z,1621311660.793 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2021-05-18T04:21:00.851Z,1621311660.851 [NAL9602] Loaded
2021-05-18T04:21:00.851Z,1621311660.851 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2021-05-18T04:21:00.879Z,1621311660.879 [Onboard] Loaded
2021-05-18T04:21:00.880Z,1621311660.880 [ComponentRegistry](DEBUG): Component "Onboard" handled in its own thread.
2021-05-18T04:21:00.881Z,1621311660.881 [Onboard ThreadHandler](DEBUG): Created PCaller Thread at 408AD4E0
2021-05-18T04:21:00.881Z,1621311660.881 [Onboard ThreadHandler](INFO): Protected caller Thread ID is 4871
2021-05-18T04:21:00.893Z,1621311660.893 [Power24vConverter] Loaded
2021-05-18T04:21:00.893Z,1621311660.893 [ComponentRegistry](DEBUG): SyncComponent "Power24vConverter" handled in the control thread.
2021-05-18T04:21:00.906Z,1621311660.906 [Radio_Surface] Loaded
2021-05-18T04:21:00.906Z,1621311660.906 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2021-05-18T04:21:00.907Z,1621311660.907 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 408DD4E0
2021-05-18T04:21:00.907Z,1621311660.907 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 4872
2021-05-18T04:21:00.928Z,1621311660.928 [AMEcho] Loaded
2021-05-18T04:21:00.928Z,1621311660.928 [ComponentRegistry](DEBUG): SyncComponent "AMEcho" handled in the control thread.
2021-05-18T04:21:01.007Z,1621311661.007 [DAT] Loaded
2021-05-18T04:21:01.007Z,1621311661.007 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread.
2021-05-18T04:21:01.008Z,1621311661.008 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2021-05-18T04:21:01.008Z,1621311661.008 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2021-05-18T04:21:01.049Z,1621311661.049 [DepthRateCalculator] Loaded
2021-05-18T04:21:01.049Z,1621311661.049 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2021-05-18T04:21:01.054Z,1621311661.054 [PitchRateCalculator] Loaded
2021-05-18T04:21:01.054Z,1621311661.054 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2021-05-18T04:21:01.063Z,1621311661.063 [SpeedCalculator] Loaded
2021-05-18T04:21:01.063Z,1621311661.063 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2021-05-18T04:21:01.077Z,1621311661.077 [TempGradientCalculator] Loaded
2021-05-18T04:21:01.077Z,1621311661.077 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2021-05-18T04:21:01.081Z,1621311661.081 [YawRateCalculator] Loaded
2021-05-18T04:21:01.081Z,1621311661.081 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2021-05-18T04:21:01.099Z,1621311661.099 [ElevatorOffsetCalculator] Loaded
2021-05-18T04:21:01.099Z,1621311661.099 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2021-05-18T04:21:01.099Z,1621311661.099 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2021-05-18T04:21:01.100Z,1621311661.100 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2021-05-18T04:21:01.268Z,1621311661.268 [CTD_Seabird] Loaded
2021-05-18T04:21:01.269Z,1621311661.269 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread.
2021-05-18T04:21:01.270Z,1621311661.270 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 409904E0
2021-05-18T04:21:01.270Z,1621311661.270 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 4873
2021-05-18T04:21:01.289Z,1621311661.289 [PAR_Licor] Loaded
2021-05-18T04:21:01.289Z,1621311661.289 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2021-05-18T04:21:01.321Z,1621311661.321 [WetLabsBB2FL] Loaded
2021-05-18T04:21:01.321Z,1621311661.321 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2021-05-18T04:21:01.322Z,1621311661.322 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 409C04E0
2021-05-18T04:21:01.322Z,1621311661.322 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 4874
2021-05-18T04:21:01.323Z,1621311661.323 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2021-05-18T04:21:01.324Z,1621311661.324 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2021-05-18T04:21:01.351Z,1621311661.351 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2021-05-18T04:21:01.351Z,1621311661.351 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2021-05-18T04:21:01.668Z,1621311661.668 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2021-05-18T04:21:01.669Z,1621311661.669 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2021-05-18T04:21:01.811Z,1621311661.811 [SBIT](DEBUG): Construct Startup Built In Test.
2021-05-18T04:21:01.820Z,1621311661.820 [SBIT] Loaded
2021-05-18T04:21:01.820Z,1621311661.820 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2021-05-18T04:21:01.822Z,1621311661.822 [IBIT](DEBUG): Construct Initiated Built In Test.
2021-05-18T04:21:01.835Z,1621311661.835 [IBIT] Loaded
2021-05-18T04:21:01.836Z,1621311661.836 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2021-05-18T04:21:01.841Z,1621311661.841 [CBIT](DEBUG): Construct Continuous Built In Test.
2021-05-18T04:21:01.941Z,1621311661.941 [CBIT] Loaded
2021-05-18T04:21:01.941Z,1621311661.941 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2021-05-18T04:21:01.941Z,1621311661.941 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2021-05-18T04:21:01.942Z,1621311661.942 [Module Loader](DEBUG): Loading Module at Modules/Dock.so
2021-05-18T04:21:02.167Z,1621311662.167 [Module Loader](DEBUG): Loaded Module: Dock (Contains behaviors and commands for docking)
2021-05-18T04:21:02.315Z,1621311662.315 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2021-05-18T04:21:02.319Z,1621311662.319 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2021-05-18T04:21:02.329Z,1621311662.329 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2021-05-18T04:21:02.330Z,1621311662.330 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40AF14E0
2021-05-18T04:21:02.331Z,1621311662.331 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 4875
2021-05-18T04:21:02.335Z,1621311662.335 [Supervisor](INFO): Main Thread ID is 4780
2021-05-18T04:21:02.335Z,1621311662.335 [Supervisor](DEBUG): Running supervisor.
2021-05-18T04:21:02.336Z,1621311662.336 [CommandLine ThreadHandler](INFO): Handler Thread ID is 4876
2021-05-18T04:21:02.338Z,1621311662.338 [controlThread ThreadHandler](INFO): Handler Thread ID is 4877
2021-05-18T04:21:02.339Z,1621311662.339 [controlThread](DEBUG): Initializing ControlThread
2021-05-18T04:21:02.340Z,1621311662.340 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2021-05-18T04:21:02.342Z,1621311662.342 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2021-05-18T04:21:02.342Z,1621311662.342 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2021-05-18T04:21:02.343Z,1621311662.343 [LoopControl](DEBUG): Initialize LoopControlComponent.
2021-05-18T04:21:02.345Z,1621311662.345 [NavChart](DEBUG): Initialize NavChart Navigation.
2021-05-18T04:21:02.345Z,1621311662.345 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2021-05-18T04:21:02.348Z,1621311662.348 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2021-05-18T04:21:02.348Z,1621311662.348 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2021-05-18T04:21:02.349Z,1621311662.349 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2021-05-18T04:21:02.349Z,1621311662.349 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2021-05-18T04:21:02.349Z,1621311662.349 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2021-05-18T04:21:02.350Z,1621311662.350 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2021-05-18T04:21:02.355Z,1621311662.355 [SBIT](INFO): Initialize SBIT Component.
2021-05-18T04:21:02.356Z,1621311662.356 [SBIT](IMPORTANT): git: 2021-05-10
2021-05-18T04:21:02.356Z,1621311662.356 [SBIT](INFO): git hash: 03112e3e75aba085c15f5826cf8e252bb5a4e5aa
2021-05-18T04:21:02.356Z,1621311662.356 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2021-05-18T04:21:02.357Z,1621311662.357 [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 Nov 13 12:38:10 PST 2019
2021-05-18T04:21:02.358Z,1621311662.358 [SBIT](INFO): Beginning SBIT in 57.000000 seconds.
2021-05-18T04:21:02.359Z,1621311662.359 [IBIT](INFO): Initialize IBIT Component.
2021-05-18T04:21:02.360Z,1621311662.360 [CBIT](DEBUG): Initialize CBIT Component.
2021-05-18T04:21:02.361Z,1621311662.361 [logger ThreadHandler](INFO): Handler Thread ID is 4878
2021-05-18T04:21:02.371Z,1621311662.371 [CBIT](DEBUG): Initialized mux pins.
2021-05-18T04:21:02.371Z,1621311662.371 [CBIT](DEBUG): Initializing the watchdog timer.
2021-05-18T04:21:02.379Z,1621311662.379 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 4879
2021-05-18T04:21:02.380Z,1621311662.380 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2021-05-18T04:21:02.391Z,1621311662.391 [Onboard ThreadHandler](INFO): Handler Thread ID is 4880
2021-05-18T04:21:02.396Z,1621311662.396 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2021-05-18T04:21:02.396Z,1621311662.396 [CBIT](DEBUG): Initializing heartbeat.
2021-05-18T04:21:02.412Z,1621311662.412 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 4881
2021-05-18T04:21:02.423Z,1621311662.423 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 4882
2021-05-18T04:21:02.424Z,1621311662.424 [CTD_Seabird](DEBUG): Initializing CTD_Seabird.
2021-05-18T04:21:02.429Z,1621311662.429 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 4884
2021-05-18T04:21:02.432Z,1621311662.432 [WetLabsBB2FL](INFO): Powering up
2021-05-18T04:21:02.433Z,1621311662.433 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 4886
2021-05-18T04:21:02.436Z,1621311662.436 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2021-05-18T04:21:02.436Z,1621311662.436 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2021-05-18T04:21:02.437Z,1621311662.437 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2021-05-18T04:21:02.437Z,1621311662.437 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2021-05-18T04:21:02.437Z,1621311662.437 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2021-05-18T04:21:02.437Z,1621311662.437 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2021-05-18T04:21:02.437Z,1621311662.437 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2021-05-18T04:21:02.437Z,1621311662.437 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2021-05-18T04:21:02.438Z,1621311662.438 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2021-05-18T04:21:02.438Z,1621311662.438 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2021-05-18T04:21:02.438Z,1621311662.438 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2021-05-18T04:21:02.438Z,1621311662.438 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2021-05-18T04:21:02.438Z,1621311662.438 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2021-05-18T04:21:02.438Z,1621311662.438 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2021-05-18T04:21:02.439Z,1621311662.439 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2021-05-18T04:21:02.439Z,1621311662.439 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2021-05-18T04:21:02.467Z,1621311662.467 [CBIT](DEBUG): Deactivating GF circuits.
2021-05-18T04:21:02.467Z,1621311662.467 [CBIT](DEBUG): Deactivating emergency mode.
2021-05-18T04:21:02.503Z,1621311662.503 [CBIT](DEBUG): Backplane powered.
2021-05-18T04:21:02.504Z,1621311662.504 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2021-05-18T04:21:02.517Z,1621311662.517 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2021-05-18T04:21:02.536Z,1621311662.536 [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-05-18T04:21:02.537Z,1621311662.537 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2021-05-18T04:21:02.614Z,1621311662.614 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2021-05-18T04:21:02.616Z,1621311662.616 [Default:A.Wait](DEBUG): Construct Wait.
2021-05-18T04:21:02.618Z,1621311662.618 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2021-05-18T04:21:02.661Z,1621311662.661 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2021-05-18T04:21:02.664Z,1621311662.664 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2021-05-18T04:21:02.685Z,1621311662.685 [Default:E.Execute](DEBUG): Construct Execute.
2021-05-18T04:21:02.689Z,1621311662.689 [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="P5M"/>
            <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>5</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-05-18T04:21:02.699Z,1621311662.699 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,BPC1,Depth_Keller,NAL9602,Power24vConverter,AMEcho,DAT,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-05-18T04:21:02.711Z,1621311662.711 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2021-05-18T04:21:02.780Z,1621311662.780 [Depth_Keller](ERROR): Pressure reading out of range: 1831.023193 decibar
2021-05-18T04:21:02.781Z,1621311662.781 [Power24vConverter](INFO): Powering down.
2021-05-18T04:21:02.781Z,1621311662.781 [AMEcho](INFO): Powering up.
2021-05-18T04:21:02.799Z,1621311662.799 [DAT](INFO): Powering up
2021-05-18T04:21:02.800Z,1621311662.800 [DAT](DEBUG): Initializing DAT.
2021-05-18T04:21:02.815Z,1621311662.815 [Radio_Surface](INFO): Powering up
2021-05-18T04:21:02.924Z,1621311662.924 [DepthRateCalculator](ERROR): Depth measurement is not active
2021-05-18T04:21:02.962Z,1621311662.962 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2021-05-18T04:21:02.967Z,1621311662.967 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2021-05-18T04:21:02.968Z,1621311662.968 [ElevatorServo](DEBUG): Initializing EZServoServo.
2021-05-18T04:21:02.975Z,1621311662.975 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2021-05-18T04:21:02.977Z,1621311662.977 [MassServo](DEBUG): Initializing EZServoServo.
2021-05-18T04:21:02.983Z,1621311662.983 [MassServo](DEBUG): Initializing MassServo.
2021-05-18T04:21:02.984Z,1621311662.984 [RudderServo](DEBUG): Initializing EZServoServo.
2021-05-18T04:21:02.991Z,1621311662.991 [RudderServo](DEBUG): Initializing RudderServo.
2021-05-18T04:21:02.993Z,1621311662.993 [ThrusterServo](DEBUG): Initializing EZServoServo.
2021-05-18T04:21:02.999Z,1621311662.999 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2021-05-18T04:21:03.407Z,1621311663.407 [AMEcho](INFO): Powering down.
2021-05-18T04:21:03.520Z,1621311663.520 [Power24vConverter](INFO): Powering up.
2021-05-18T04:21:03.871Z,1621311663.871 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2021-05-18T04:21:03.871Z,1621311663.871 [RudderServo](FAULT): Rudder failed to initialize
2021-05-18T04:21:03.871Z,1621311663.871 [RudderServo] Communications Fault, FailCount= 1
2021-05-18T04:21:03.871Z,1621311663.871 [RudderServo](ERROR): Communications Fault
2021-05-18T04:21:03.974Z,1621311663.974 [CBIT](ERROR): Communications Fault in component: RudderServo
2021-05-18T04:21:03.985Z,1621311663.985 [AMEcho](IMPORTANT): Setting 'depthThreshold' to 20.000000
2021-05-18T04:21:04.140Z,1621311664.140 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2021-05-18T04:21:04.140Z,1621311664.140 [RudderServo](INFO): Powering down
2021-05-18T04:21:04.539Z,1621311664.539 [WetLabsBB2FL](INFO): Powering down
2021-05-18T04:21:04.811Z,1621311664.811 [RudderServo](DEBUG): Initializing EZServoServo.
2021-05-18T04:21:04.932Z,1621311664.932 [RudderServo](DEBUG): Initializing RudderServo.
2021-05-18T04:21:04.936Z,1621311664.936 [CBIT](INFO): Clearing failed state for component RudderServo
2021-05-18T04:21:04.936Z,1621311664.936 [RudderServo] No Fault, FailCount= 1
2021-05-18T04:21:09.456Z,1621311669.456 [CTD_Seabird](ERROR): Device message queue exceeded the allowed limit.
2021-05-18T04:21:14.489Z,1621311674.489 [DAT](INFO): DAT read: 

2021-05-18T04:21:14.490Z,1621311674.490 [DAT](INFO): DAT read: Teledyne Benthos DAT-900 Series

2021-05-18T04:21:15.125Z,1621311675.125 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004706
2021-05-18T04:21:16.106Z,1621311676.106 [DAT](INFO): DAT read: MF Frequency Band

2021-05-18T04:21:16.107Z,1621311676.107 [DAT](INFO): DAT read: Directional Acoustic Transponder version 8.14.2

2021-05-18T04:21:16.108Z,1621311676.108 [DAT](INFO): DAT read: May 18 2021 04:20:45 

2021-05-18T04:21:16.913Z,1621311676.913 [DAT](INFO): DAT read: Features enabled [Bearing]

2021-05-18T04:21:16.915Z,1621311676.915 [DAT](INFO): DAT read: CONNECT 00800 bits/sec 1 of 4, Rate 1/2 CC 12.50ms MGP

2021-05-18T04:21:16.915Z,1621311676.915 [DAT](INFO): commRate: 800
2021-05-18T04:21:18.933Z,1621311678.933 [DAT](INFO): entering command mode
2021-05-18T04:21:19.337Z,1621311679.337 [DAT](INFO): DAT read: 

2021-05-18T04:21:19.337Z,1621311679.337 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:21:19.753Z,1621311679.753 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:21:20.149Z,1621311680.149 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:21:20.549Z,1621311680.549 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:21:20.953Z,1621311680.953 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:21:21.357Z,1621311681.357 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:21:21.761Z,1621311681.761 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:21:22.173Z,1621311682.173 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:21:22.573Z,1621311682.573 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:21:22.973Z,1621311682.973 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:21:23.377Z,1621311683.377 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:21:23.781Z,1621311683.781 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:21:24.189Z,1621311684.189 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:21:24.589Z,1621311684.589 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:21:24.993Z,1621311684.993 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:21:25.397Z,1621311685.397 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:21:25.801Z,1621311685.801 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:21:26.205Z,1621311686.205 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:21:26.609Z,1621311686.609 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:21:27.025Z,1621311687.025 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:21:27.425Z,1621311687.425 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:21:27.821Z,1621311687.821 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:21:28.225Z,1621311688.225 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:21:28.633Z,1621311688.633 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:21:29.033Z,1621311689.033 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:21:29.437Z,1621311689.437 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:21:29.841Z,1621311689.841 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:21:30.251Z,1621311690.251 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:21:30.649Z,1621311690.649 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:21:31.053Z,1621311691.053 [NAL9602](INFO): Powering up NAL9602
2021-05-18T04:21:31.054Z,1621311691.054 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:21:31.457Z,1621311691.457 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:21:31.867Z,1621311691.867 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:21:32.265Z,1621311692.265 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:21:32.669Z,1621311692.669 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:21:33.073Z,1621311693.073 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:21:33.481Z,1621311693.481 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:21:33.881Z,1621311693.881 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:21:34.285Z,1621311694.285 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:21:34.285Z,1621311694.285 [DAT](FAULT): failed to enter command mode
2021-05-18T04:21:34.689Z,1621311694.689 [DAT](INFO): entering command mode
2021-05-18T04:21:35.093Z,1621311695.093 [DAT](INFO): DAT read: user:1>

2021-05-18T04:21:35.094Z,1621311695.094 [DAT](INFO): DAT read: Command '+++' not found

2021-05-18T04:21:35.094Z,1621311695.094 [DAT](INFO): DAT read: Error

2021-05-18T04:21:35.095Z,1621311695.095 [DAT](INFO): setting verbose to 3
2021-05-18T04:21:35.497Z,1621311695.497 [DAT](INFO): DAT read: user:2>

2021-05-18T04:21:35.498Z,1621311695.498 [DAT](INFO): DAT read: Verbose         | 3           

2021-05-18T04:21:35.498Z,1621311695.498 [DAT](INFO): set verbose to 3
2021-05-18T04:21:35.499Z,1621311695.499 [DAT](INFO): setting DatVerbose to 27440
2021-05-18T04:21:35.901Z,1621311695.901 [DAT](INFO): DAT read: user:3>

2021-05-18T04:21:35.902Z,1621311695.902 [DAT](INFO): DAT read: DatVerbose      | 27440       

2021-05-18T04:21:35.902Z,1621311695.902 [DAT](INFO): set DatVerbose to 27440
2021-05-18T04:21:35.903Z,1621311695.903 [DAT](INFO): setting transmit power to 8
2021-05-18T04:21:36.305Z,1621311696.305 [DAT](INFO): DAT read: user:4>

2021-05-18T04:21:36.306Z,1621311696.306 [DAT](INFO): DAT read: TxPower         | 8 (Max)     

2021-05-18T04:21:36.306Z,1621311696.306 [DAT](INFO): set transmit power to 8
2021-05-18T04:21:36.307Z,1621311696.307 [DAT](INFO): setting local address to 7
2021-05-18T04:21:36.709Z,1621311696.709 [DAT](INFO): DAT read: user:5>

2021-05-18T04:21:36.710Z,1621311696.710 [DAT](INFO): DAT read: LocalAddr       | 7           

2021-05-18T04:21:36.711Z,1621311696.711 [DAT](INFO): set local address to 7
2021-05-18T04:21:41.977Z,1621311701.977 [NAL9602](INFO): NAL9602 initialized
2021-05-18T04:22:00.159Z,1621311720.159 [SBIT](IMPORTANT): Beginning Startup BIT
2021-05-18T04:22:00.163Z,1621311720.163 [CBIT](IMPORTANT): Beginning ground fault scan
2021-05-18T04:22:11.136Z,1621311731.136 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): 0.016693
CHAN A1 (24V): 0.000460
CHAN A2 (12V): -0.002103
CHAN A3 (5V): -0.001533
CHAN B0 (3.3V): -0.000019
CHAN B1 (3.15aV): -0.000482
CHAN B2 (3.15bV): -0.000282
CHAN B3 (GND): -0.000347
OPEN: -0.000750
Full Scale Calc: 4.765 mA, -1.589 mA
2021-05-18T04:22:54.314Z,1621311774.314 [SBIT](IMPORTANT): SBIT PASSED
2021-05-18T04:22:54.314Z,1621311774.314 [SBIT](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2021-05-18T04:22:54.315Z,1621311774.315 [SBIT](IMPORTANT): DAT.verbosity=3 count;

2021-05-18T04:22:54.315Z,1621311774.315 [SBIT](IMPORTANT): DropWeight.loadAtStartup=0 bool;

2021-05-18T04:22:54.315Z,1621311774.315 [SBIT](IMPORTANT): VerticalControl.buoyancyNeutral=282 cubic_centimeter;

2021-05-18T04:22:54.315Z,1621311774.315 [SBIT](IMPORTANT): VerticalControl.massDefault=9.25 millimeter;

2021-05-18T04:22:54.700Z,1621311774.700 [MissionManager](IMPORTANT): Started mission Startup
2021-05-18T04:22:54.700Z,1621311774.700 [Startup] Running Loop=1
2021-05-18T04:22:54.701Z,1621311774.701 [Startup](DEBUG): Aggregate::initialize Startup
2021-05-18T04:22:54.701Z,1621311774.701 [Startup:A.GoToSurface] Running Loop=1
2021-05-18T04:22:54.701Z,1621311774.701 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2021-05-18T04:22:54.701Z,1621311774.701 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2021-05-18T04:22:54.702Z,1621311774.702 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2021-05-18T04:22:54.702Z,1621311774.702 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2021-05-18T04:22:54.702Z,1621311774.702 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2021-05-18T04:22:54.735Z,1621311774.735 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2021-05-18T04:22:54.737Z,1621311774.737 [Startup:StartupSatComms] Running Loop=1
2021-05-18T04:22:54.737Z,1621311774.737 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2021-05-18T04:22:54.737Z,1621311774.737 [Startup:StartupSatComms:A] Running Loop=1
2021-05-18T04:22:55.100Z,1621311775.100 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2021-05-18T04:22:55.493Z,1621311775.493 [AMEcho](INFO): Powering up.
2021-05-18T04:23:54.898Z,1621311834.898 [Startup:StartupSatComms:A](INFO): Timed out from 2021-05-18T04:22:54.7Z
2021-05-18T04:23:54.898Z,1621311834.898 [Startup:StartupSatComms:A] Stopped
2021-05-18T04:23:54.898Z,1621311834.898 [Startup:StartupSatComms:B] Running Loop=1
2021-05-18T04:23:55.301Z,1621311835.301 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2021-05-18T04:24:01.691Z,1621311841.691 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20210517T203015/Courier0109.lzma
2021-05-18T04:24:02.593Z,1621311842.593 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2021-05-18T04:24:02.593Z,1621311842.593 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-05-18T04:24:02.604Z,1621311842.604 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-05-18T04:24:02.693Z,1621311842.693 [DataOverHttps](INFO): Moved sent file to Logs/20210517T203015/Courier0109.lzma.bak
2021-05-18T04:24:02.693Z,1621311842.693 [DataOverHttps](INFO): SBD MOMSN=15648298
2021-05-18T04:24:03.001Z,1621311843.001 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-05-18T04:24:03.002Z,1621311843.002 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2021-05-18T04:24:18.162Z,1621311858.162 [DataOverHttps](INFO): Sending 151 bytes from file Logs/20210518T024943/Courier0000.lzma
2021-05-18T04:24:19.173Z,1621311859.173 [DataOverHttps](INFO): Moved sent file to Logs/20210518T024943/Courier0000.lzma.bak
2021-05-18T04:24:19.173Z,1621311859.173 [DataOverHttps](INFO): SBD MOMSN=15648300
2021-05-18T04:24:34.595Z,1621311874.595 [DataOverHttps](INFO): Sending 202 bytes from file Logs/20210518T025202/Courier0000.lzma
2021-05-18T04:24:35.593Z,1621311875.593 [DataOverHttps](INFO): Moved sent file to Logs/20210518T025202/Courier0000.lzma.bak
2021-05-18T04:24:35.593Z,1621311875.593 [DataOverHttps](INFO): SBD MOMSN=15648303
2021-05-18T04:24:36.529Z,1621311876.529 [DAT](INFO): DAT read: user:6>Lowpower

2021-05-18T04:24:36.529Z,1621311876.529 [DAT](DEBUG): Re-entering command mode due to deviceResponse_: user:6>Lowpower

2021-05-18T04:24:51.303Z,1621311891.303 [DataOverHttps](INFO): Sending 151 bytes from file Logs/20210518T025530/Courier0000.lzma
2021-05-18T04:24:52.321Z,1621311892.321 [DataOverHttps](INFO): Moved sent file to Logs/20210518T025530/Courier0000.lzma.bak
2021-05-18T04:24:52.321Z,1621311892.321 [DataOverHttps](INFO): SBD MOMSN=15648307
2021-05-18T04:24:55.109Z,1621311895.109 [Startup:StartupSatComms:B](INFO): Timed out from 2021-05-18T04:23:54.9Z
2021-05-18T04:24:55.110Z,1621311895.110 [Startup:StartupSatComms:B] Stopped
2021-05-18T04:24:55.110Z,1621311895.110 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2021-05-18T04:24:55.110Z,1621311895.110 [Startup:StartupSatComms] Stopped
2021-05-18T04:24:55.110Z,1621311895.110 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2021-05-18T04:24:55.111Z,1621311895.111 [Startup](INFO): Completed Startup
2021-05-18T04:24:55.111Z,1621311895.111 [MissionManager](INFO): Startup is completed.
2021-05-18T04:24:55.111Z,1621311895.111 [MissionManager](INFO): Uninitializing Mission Startup
2021-05-18T04:24:55.111Z,1621311895.111 [Startup] Stopped
2021-05-18T04:24:55.111Z,1621311895.111 [Startup](DEBUG): Aggregate::uninitialize Startup
2021-05-18T04:24:55.111Z,1621311895.111 [Startup:A.GoToSurface] Stopped
2021-05-18T04:24:55.111Z,1621311895.111 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2021-05-18T04:24:55.521Z,1621311895.521 [MissionManager](IMPORTANT): Started mission Default
2021-05-18T04:24:55.522Z,1621311895.522 [Default] Running Loop=1
2021-05-18T04:24:55.522Z,1621311895.522 [Default](DEBUG): Aggregate::initialize Default
2021-05-18T04:24:55.522Z,1621311895.522 [Default:B.GoToSurface] Running Loop=1
2021-05-18T04:24:55.522Z,1621311895.522 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2021-05-18T04:24:55.522Z,1621311895.522 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2021-05-18T04:24:55.522Z,1621311895.522 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2021-05-18T04:24:55.527Z,1621311895.527 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2021-05-18T04:24:55.527Z,1621311895.527 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2021-05-18T04:24:55.528Z,1621311895.528 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2021-05-18T04:24:55.528Z,1621311895.528 [Default:A.Wait] Running Loop=1
2021-05-18T04:24:55.528Z,1621311895.528 [Default:A.Wait](DEBUG): Initialize Wait Component.
2021-05-18T04:24:56.075Z,1621311896.075 [AMEcho](INFO): Powering down.
2021-05-18T04:24:57.122Z,1621311897.122 [AMEcho](INFO): Powering up.
2021-05-18T04:25:08.850Z,1621311908.850 [DataOverHttps](INFO): Sending 151 bytes from file Logs/20210518T042051/Courier0000.lzma
2021-05-18T04:25:08.860Z,1621311908.860 [Default:A.Wait](INFO): Done Waiting.
2021-05-18T04:25:08.860Z,1621311908.860 [Default:A.Wait] Stopped
2021-05-18T04:25:08.860Z,1621311908.860 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2021-05-18T04:25:09.248Z,1621311909.248 [AMEcho](ERROR): No EchoSounder communication! Re-initializing
2021-05-18T04:25:09.248Z,1621311909.248 [AMEcho] Communications Fault, FailCount= 1
2021-05-18T04:25:09.248Z,1621311909.248 [AMEcho](ERROR): Communications Fault
2021-05-18T04:25:09.288Z,1621311909.288 [Default:CheckIn] Running Loop=1
2021-05-18T04:25:09.288Z,1621311909.288 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-05-18T04:25:09.289Z,1621311909.289 [Default:CheckIn:Read_GPS] Running Loop=1
2021-05-18T04:25:09.305Z,1621311909.305 [CBIT](ERROR): Communications Fault in component: AMEcho
2021-05-18T04:25:09.815Z,1621311909.815 [AMEcho](INFO): Powering down.
2021-05-18T04:25:09.838Z,1621311909.838 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2021-05-18T04:25:09.853Z,1621311909.853 [DataOverHttps](INFO): Moved sent file to Logs/20210518T042051/Courier0000.lzma.bak
2021-05-18T04:25:09.853Z,1621311909.853 [DataOverHttps](INFO): SBD MOMSN=15648310
2021-05-18T04:25:10.495Z,1621311910.495 [CBIT](INFO): Clearing failed state for component AMEcho
2021-05-18T04:25:10.495Z,1621311910.495 [AMEcho] No Fault, FailCount= 1
2021-05-18T04:25:10.853Z,1621311910.853 [AMEcho](INFO): Powering up.
2021-05-18T04:25:22.973Z,1621311922.973 [AMEcho](ERROR): No EchoSounder communication! Re-initializing
2021-05-18T04:25:22.973Z,1621311922.973 [AMEcho] Communications Fault, FailCount= 2
2021-05-18T04:25:22.973Z,1621311922.973 [AMEcho](ERROR): Communications Fault
2021-05-18T04:25:22.994Z,1621311922.994 [CBIT](ERROR): Communications Fault in component: AMEcho
2021-05-18T04:25:23.567Z,1621311923.567 [AMEcho](INFO): Powering down.
2021-05-18T04:25:24.205Z,1621311924.205 [CBIT](INFO): Clearing failed state for component AMEcho
2021-05-18T04:25:24.205Z,1621311924.205 [AMEcho] No Fault, FailCount= 2
2021-05-18T04:25:24.593Z,1621311924.593 [AMEcho](INFO): Powering up.
2021-05-18T04:25:36.728Z,1621311936.728 [AMEcho](ERROR): No EchoSounder communication! Re-initializing
2021-05-18T04:25:36.728Z,1621311936.728 [AMEcho] Communications Fault, FailCount= 3
2021-05-18T04:25:36.728Z,1621311936.728 [AMEcho](ERROR): Communications Fault
2021-05-18T04:25:36.796Z,1621311936.796 [CBIT](ERROR): Communications Fault in component: AMEcho
2021-05-18T04:25:36.797Z,1621311936.797 [CBIT](CRITICAL): Communications Fault in component: AMEcho
2021-05-18T04:25:37.279Z,1621311937.279 [AMEcho](INFO): Powering down.
2021-05-18T04:25:37.320Z,1621311937.320 [CommandLine](FAULT): Scheduling is paused
2021-05-18T04:25:37.321Z,1621311937.321 [CBIT](INFO): Critical error at 20210518T042536
2021-05-18T04:25:37.321Z,1621311937.321 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals
2021-05-18T04:26:45.392Z,1621312005.392 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2021-05-18T04:26:49.500Z,1621312009.500 [CommandLine](IMPORTANT): got command failComponent
2021-05-18T04:26:49.500Z,1621312009.500 [CommandLine](IMPORTANT): Failed components:
2021-05-18T04:26:49.500Z,1621312009.500 [CommandLine](IMPORTANT): AMEcho: Communications Fault
2021-05-18T04:26:59.401Z,1621312019.401 [CommandLine](IMPORTANT): got command show 
2021-05-18T04:26:59.401Z,1621312019.401 [CommandLine](FAULT): Incomplete syntax. Try: help show
2021-05-18T04:27:03.646Z,1621312023.646 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2
2021-05-18T04:27:03.647Z,1621312023.647 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2021-05-18T04:27:03.657Z,1621312023.657 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2021-05-18T04:27:04.050Z,1621312024.050 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2021-05-18T04:27:04.050Z,1621312024.050 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2
2021-05-18T04:27:05.808Z,1621312025.808 [CommandLine](IMPORTANT): got command help show
2021-05-18T04:27:17.735Z,1621312037.735 [BPC1](ERROR): BPC1A: No match for serial number 1717 in BPC1A's battery stick inventory (sticks 1-32 in onboard configuration file).
2021-05-18T04:27:25.725Z,1621312045.725 [CommandLine](IMPORTANT): got command show variable DAT
2021-05-18T04:27:25.796Z,1621312045.796 [CommandLine](IMPORTANT): DeadReckonUsingMultipleVelocitySources.loadAtStartup (bool)
2021-05-18T04:27:25.797Z,1621312045.797 [CommandLine](IMPORTANT): DeadReckonUsingSpeedCalculator.loadAtStartup (bool)
2021-05-18T04:27:25.798Z,1621312045.798 [CommandLine](IMPORTANT): DeadReckonWithRespectToWater.loadAtStartup (bool)
2021-05-18T04:27:25.803Z,1621312045.803 [CommandLine](IMPORTANT): DeadReckonWithRespectToSeafloor.loadAtStartup (bool)
2021-05-18T04:27:25.804Z,1621312045.804 [CommandLine](IMPORTANT): DeadReckonUsingDVLWaterTrack.loadAtStartup (bool)
2021-05-18T04:27:25.805Z,1621312045.805 [CommandLine](IMPORTANT): DeadReckonUsingCompactModelForecast.loadAtStartup (bool)
2021-05-18T04:27:25.805Z,1621312045.805 [CommandLine](IMPORTANT): LBLNavigation.loadAtStartup (bool)
2021-05-18T04:27:25.806Z,1621312045.806 [CommandLine](IMPORTANT): NavChart.loadAtStartup (bool)
2021-05-18T04:27:25.806Z,1621312045.806 [CommandLine](IMPORTANT): UniversalFixResidualReporter.loadAtStartup (bool)
2021-05-18T04:27:25.848Z,1621312045.848 [CommandLine](IMPORTANT): WorkSite.loadAtStartup (bool)
2021-05-18T04:27:25.848Z,1621312045.848 [CommandLine](IMPORTANT): ExternalSim.loadAtStartup (bool)
2021-05-18T04:27:25.849Z,1621312045.849 [CommandLine](IMPORTANT): InternalSim.loadAtStartup (bool)
2021-05-18T04:27:25.849Z,1621312045.849 [CommandLine](IMPORTANT): NavigationSim.loadAtStartup (bool)
2021-05-18T04:27:25.862Z,1621312045.862 [CommandLine](IMPORTANT): Config/Simulator.oceanModelData (none)
2021-05-18T04:27:25.862Z,1621312045.862 [CommandLine](IMPORTANT): HorizontalControl.loadAtStartup (bool)
2021-05-18T04:27:25.871Z,1621312045.871 [CommandLine](IMPORTANT): LoopControl.loadAtStartup (bool)
2021-05-18T04:27:25.879Z,1621312045.879 [CommandLine](IMPORTANT): SpeedControl.loadAtStartup (bool)
2021-05-18T04:27:25.880Z,1621312045.880 [CommandLine](IMPORTANT): VerticalControl.loadAtStartup (bool)
2021-05-18T04:27:25.891Z,1621312045.891 [CommandLine](IMPORTANT): BuoyancyServo.loadAtStartup (bool)
2021-05-18T04:27:25.893Z,1621312045.893 [CommandLine](IMPORTANT): DockingServo.loadAtStartup (bool)
2021-05-18T04:27:25.894Z,1621312045.894 [CommandLine](IMPORTANT): ElevatorServo.loadAtStartup (bool)
2021-05-18T04:27:25.904Z,1621312045.904 [CommandLine](IMPORTANT): MassServo.loadAtStartup (bool)
2021-05-18T04:27:25.905Z,1621312045.905 [CommandLine](IMPORTANT): RudderServo.loadAtStartup (bool)
2021-05-18T04:27:25.906Z,1621312045.906 [CommandLine](IMPORTANT): ThrusterServo.loadAtStartup (bool)
2021-05-18T04:27:25.907Z,1621312045.907 [CommandLine](IMPORTANT): CBIT.loadAtStartup (bool)
2021-05-18T04:27:25.921Z,1621312045.921 [CommandLine](IMPORTANT): SBIT.loadAtStartup (bool)
2021-05-18T04:27:25.921Z,1621312045.921 [CommandLine](IMPORTANT): IBIT.loadAtStartup (bool)
2021-05-18T04:27:25.922Z,1621312045.922 [CommandLine](IMPORTANT): Vehicle.sendDataToShore (bool)
2021-05-18T04:27:25.934Z,1621312045.934 [CommandLine](IMPORTANT): DAT.loadControl (none)
2021-05-18T04:27:25.934Z,1621312045.934 [CommandLine](IMPORTANT): DAT.uart (none)
2021-05-18T04:27:25.934Z,1621312045.934 [CommandLine](IMPORTANT): DAT.baud (bit_per_second)
2021-05-18T04:27:25.966Z,1621312045.966 [CommandLine](IMPORTANT): AHRS_M2.loadAtStartup (bool)
2021-05-18T04:27:25.967Z,1621312045.967 [CommandLine](IMPORTANT): AMEcho.loadAtStartup (bool)
2021-05-18T04:27:25.976Z,1621312045.976 [CommandLine](IMPORTANT): AcousticModem_Benthos_ATM900.loadAtStartup (bool)
2021-05-18T04:27:25.977Z,1621312045.977 [CommandLine](IMPORTANT): BackseatComponent.loadAtStartup (bool)
2021-05-18T04:27:25.978Z,1621312045.978 [CommandLine](IMPORTANT): BPC1.loadAtStartup (bool)
2021-05-18T04:27:25.978Z,1621312045.978 [CommandLine](IMPORTANT): BR_Ping1D.loadAtStartup (bool)
2021-05-18T04:27:25.979Z,1621312045.979 [CommandLine](IMPORTANT): DataOverHttps.loadAtStartup (bool)
2021-05-18T04:27:25.980Z,1621312045.980 [CommandLine](IMPORTANT): DataOverHttps.connectionTimeout (second)
2021-05-18T04:27:25.980Z,1621312045.980 [CommandLine](IMPORTANT): DataOverHttps.period (second)
2021-05-18T04:27:25.980Z,1621312045.980 [CommandLine](IMPORTANT): DataOverHttps.power (watt)
2021-05-18T04:27:25.981Z,1621312045.981 [CommandLine](IMPORTANT): DataOverHttps.timeout (minute)
2021-05-18T04:27:25.981Z,1621312045.981 [CommandLine](IMPORTANT): DataOverHttps.verbosity (count)
2021-05-18T04:27:25.981Z,1621312045.981 [CommandLine](IMPORTANT): DAT.loadAtStartup (bool)
2021-05-18T04:27:25.982Z,1621312045.982 [CommandLine](IMPORTANT): DAT.simulateHardware (bool)
2021-05-18T04:27:25.982Z,1621312045.982 [CommandLine](IMPORTANT): DAT.maxAckTimeouts (count)
2021-05-18T04:27:25.982Z,1621312045.982 [CommandLine](IMPORTANT): DAT.convertPhaseDataToDirection (bool)
2021-05-18T04:27:25.983Z,1621312045.983 [CommandLine](IMPORTANT): DAT.ignoreElevationAngle (bool)
2021-05-18T04:27:25.988Z,1621312045.988 [CommandLine](IMPORTANT): DAT.txPower (enum)
2021-05-18T04:27:25.988Z,1621312045.988 [CommandLine](IMPORTANT): DAT.localAddress (count)
2021-05-18T04:27:25.988Z,1621312045.988 [CommandLine](IMPORTANT): DAT.sbdAddress (enum)
2021-05-18T04:27:25.989Z,1621312045.989 [CommandLine](IMPORTANT): DAT.transponderAddress (enum)
2021-05-18T04:27:25.989Z,1621312045.989 [CommandLine](IMPORTANT): DAT.sendExpress (bool)
2021-05-18T04:27:25.989Z,1621312045.989 [CommandLine](IMPORTANT): DAT.surfaceThreshold (meter)
2021-05-18T04:27:25.990Z,1621312045.990 [CommandLine](IMPORTANT): DAT.powerLoadControl (none)
2021-05-18T04:27:25.990Z,1621312045.990 [CommandLine](IMPORTANT): DAT.verbosity (count)
2021-05-18T04:27:25.990Z,1621312045.990 [CommandLine](IMPORTANT): DDM.loadAtStartup (bool)
2021-05-18T04:27:25.993Z,1621312045.993 [CommandLine](IMPORTANT): DUSBL_Hydroid.loadAtStartup (bool)
2021-05-18T04:27:26.004Z,1621312046.004 [CommandLine](IMPORTANT): Depth_Keller.loadAtStartup (bool)
2021-05-18T04:27:26.004Z,1621312046.004 [CommandLine](IMPORTANT): DropWeight.loadAtStartup (bool)
2021-05-18T04:27:26.005Z,1621312046.005 [CommandLine](IMPORTANT): DVL_micro.loadAtStartup (bool)
2021-05-18T04:27:26.005Z,1621312046.005 [CommandLine](IMPORTANT): GobyModem.loadAtStartup (bool)
2021-05-18T04:27:26.006Z,1621312046.006 [CommandLine](IMPORTANT): Micromodem.loadAtStartup (bool)
2021-05-18T04:27:26.016Z,1621312046.016 [CommandLine](IMPORTANT): Micromodem.dataRate (enum)
2021-05-18T04:27:26.017Z,1621312046.017 [CommandLine](IMPORTANT): NAL9602.loadAtStartup (bool)
2021-05-18T04:27:26.017Z,1621312046.017 [CommandLine](IMPORTANT): Onboard.loadAtStartup (bool)
2021-05-18T04:27:26.018Z,1621312046.018 [CommandLine](IMPORTANT): Power24vConverter.loadAtStartup (bool)
2021-05-18T04:27:26.019Z,1621312046.019 [CommandLine](IMPORTANT): PowerOnly.loadAtStartup (bool)
2021-05-18T04:27:26.019Z,1621312046.019 [CommandLine](IMPORTANT): PNI_TCM.loadAtStartup (bool)
2021-05-18T04:27:26.020Z,1621312046.020 [CommandLine](IMPORTANT): Radio_Surface.loadAtStartup (bool)
2021-05-18T04:27:26.020Z,1621312046.020 [CommandLine](IMPORTANT): RDI_Pathfinder.loadAtStartup (bool)
2021-05-18T04:27:26.021Z,1621312046.021 [CommandLine](IMPORTANT): RDI_PathfinderUp.loadAtStartup (bool)
2021-05-18T04:27:26.021Z,1621312046.021 [CommandLine](IMPORTANT): Rowe_600.loadAtStartup (bool)
2021-05-18T04:27:26.022Z,1621312046.022 [CommandLine](IMPORTANT): SCPI.loadAtStartup (bool)
2021-05-18T04:27:26.031Z,1621312046.031 [CommandLine](IMPORTANT): Aanderaa_O2.loadAtStartup (bool)
2021-05-18T04:27:26.032Z,1621312046.032 [CommandLine](IMPORTANT): CANONSampler.loadAtStartup (bool)
2021-05-18T04:27:26.032Z,1621312046.032 [CommandLine](IMPORTANT): CTD_NeilBrown.loadAtStartup (bool)
2021-05-18T04:27:26.033Z,1621312046.033 [CommandLine](IMPORTANT): CTD_Seabird.loadAtStartup (bool)
2021-05-18T04:27:26.041Z,1621312046.041 [CommandLine](IMPORTANT): ESPComponent.loadAtStartup (bool)
2021-05-18T04:27:26.042Z,1621312046.042 [CommandLine](IMPORTANT): PAR_Licor.loadAtStartup (bool)
2021-05-18T04:27:26.051Z,1621312046.051 [CommandLine](IMPORTANT): VemcoVR2C.loadAtStartup (bool)
2021-05-18T04:27:26.052Z,1621312046.052 [CommandLine](IMPORTANT): WetLabsBB2FL.loadAtStartup (bool)
2021-05-18T04:27:26.053Z,1621312046.053 [CommandLine](IMPORTANT): WetLabsSeaOWL_UV_A.loadAtStartup (bool)
2021-05-18T04:27:26.054Z,1621312046.054 [CommandLine](IMPORTANT): WetLabsUBAT.loadAtStartup (bool)
2021-05-18T04:27:26.054Z,1621312046.054 [CommandLine](IMPORTANT): StratificationFrontDetector.loadAtStartup (bool)
2021-05-18T04:27:26.063Z,1621312046.063 [CommandLine](IMPORTANT): DepAvgTempFrontDetector.loadAtStartup (bool)
2021-05-18T04:27:26.064Z,1621312046.064 [CommandLine](IMPORTANT): DepthRateCalculator.loadAtStartup (bool)
2021-05-18T04:27:26.064Z,1621312046.064 [CommandLine](IMPORTANT): TempGradientCalculator.loadAtStartup (bool)
2021-05-18T04:27:26.065Z,1621312046.065 [CommandLine](IMPORTANT): PitchRateCalculator.loadAtStartup (bool)
2021-05-18T04:27:26.065Z,1621312046.065 [CommandLine](IMPORTANT): SpeedCalculator.loadAtStartup (bool)
2021-05-18T04:27:26.066Z,1621312046.066 [CommandLine](IMPORTANT): VerticalTemperatureHomogeneityIndexCalculator.loadAtStartup (bool)
2021-05-18T04:27:26.067Z,1621312046.067 [CommandLine](IMPORTANT): YawRateCalculator.loadAtStartup (bool)
2021-05-18T04:27:26.079Z,1621312046.079 [CommandLine](IMPORTANT): ElevatorOffsetCalculator.loadAtStartup (bool)
2021-05-18T04:27:26.080Z,1621312046.080 [CommandLine](IMPORTANT): Docked.dataTimeout (second)
2021-05-18T04:27:26.126Z,1621312046.126 [CommandLine](IMPORTANT): DataOverHttps.enableBroadcast (bool)
2021-05-18T04:27:26.126Z,1621312046.126 [CommandLine](IMPORTANT): DataOverHttps.platform_communications (bool)
2021-05-18T04:27:26.127Z,1621312046.127 [CommandLine](IMPORTANT): DataOverHttps.connectionStatus (bool)
2021-05-18T04:27:26.134Z,1621312046.134 [CommandLine](IMPORTANT): DAT.enableBroadcast (bool)
2021-05-18T04:27:26.134Z,1621312046.134 [CommandLine](IMPORTANT): DAT.component_voltage (volt)
2021-05-18T04:27:26.134Z,1621312046.134 [CommandLine](IMPORTANT): DAT.component_avgVoltage (volt)
2021-05-18T04:27:26.135Z,1621312046.135 [CommandLine](IMPORTANT): DAT.component_current (milliampere)
2021-05-18T04:27:26.139Z,1621312046.139 [CommandLine](IMPORTANT): DAT.component_avgCurrent (milliampere)
2021-05-18T04:27:26.147Z,1621312046.147 [CommandLine](IMPORTANT): DAT.acoustic_contact_address (enum)
2021-05-18T04:27:26.148Z,1621312046.148 [CommandLine](IMPORTANT): DAT.acoustic_contact_direction_vehicle_frame (none)
2021-05-18T04:27:26.148Z,1621312046.148 [CommandLine](IMPORTANT): DAT.platform_communications (bool)
2021-05-18T04:27:26.148Z,1621312046.148 [CommandLine](IMPORTANT): DAT.acoustic_contact_range (meter)
2021-05-18T04:27:26.149Z,1621312046.149 [CommandLine](IMPORTANT): DAT.acoustic_receive_time (epoch_second)
2021-05-18T04:27:26.149Z,1621312046.149 [CommandLine](IMPORTANT): DAT.acoustic_transmit_time (epoch_second)
2021-05-18T04:27:26.149Z,1621312046.149 [CommandLine](IMPORTANT): DAT.LVL1 (count)
2021-05-18T04:27:26.150Z,1621312046.150 [CommandLine](IMPORTANT): DAT.LVL2 (count)
2021-05-18T04:27:26.150Z,1621312046.150 [CommandLine](IMPORTANT): DAT.LVL3 (count)
2021-05-18T04:27:26.150Z,1621312046.150 [CommandLine](IMPORTANT): DAT.LVL4 (count)
2021-05-18T04:27:26.150Z,1621312046.150 [CommandLine](IMPORTANT): DAT.AGC (count)
2021-05-18T04:27:26.157Z,1621312046.157 [CommandLine](IMPORTANT): DAT.phaseA (radian)
2021-05-18T04:27:26.158Z,1621312046.158 [CommandLine](IMPORTANT): DAT.phaseB (radian)
2021-05-18T04:27:26.158Z,1621312046.158 [CommandLine](IMPORTANT): DAT.phaseC (radian)
2021-05-18T04:27:26.158Z,1621312046.158 [CommandLine](IMPORTANT): DAT.rawAzimuth (degree)
2021-05-18T04:27:26.159Z,1621312046.159 [CommandLine](IMPORTANT): DAT.rawElevation (degree)
2021-05-18T04:27:26.163Z,1621312046.163 [CommandLine](IMPORTANT): DAT.calibratedAzimuth (degree)
2021-05-18T04:27:26.164Z,1621312046.164 [CommandLine](IMPORTANT): DAT.calibratedElevation (degree)
2021-05-18T04:27:26.164Z,1621312046.164 [CommandLine](IMPORTANT): DAT.rotatedAzimuth (degree)
2021-05-18T04:27:26.165Z,1621312046.165 [CommandLine](IMPORTANT): DAT.rotatedElevation (degree)
2021-05-18T04:27:26.165Z,1621312046.165 [CommandLine](IMPORTANT): DAT.acoustic_wakeup (count)
2021-05-18T04:27:26.165Z,1621312046.165 [CommandLine](IMPORTANT): DAT.range_request (count)
2021-05-18T04:27:26.166Z,1621312046.166 [CommandLine](IMPORTANT): DAT.localAddressReading (enum)
2021-05-18T04:27:26.166Z,1621312046.166 [CommandLine](IMPORTANT): DAT.azimuth_instrumentFrame (radian)
2021-05-18T04:27:26.166Z,1621312046.166 [CommandLine](IMPORTANT): DAT.elevation_instrumentFrame (radian)
2021-05-18T04:27:26.166Z,1621312046.166 [CommandLine](IMPORTANT): DAT.azimuth_vehicleFrame (radian)
2021-05-18T04:27:26.167Z,1621312046.167 [CommandLine](IMPORTANT): DAT.elevation_vehicleFrame (radian)
2021-05-18T04:27:26.167Z,1621312046.167 [CommandLine](IMPORTANT): DAT.direction_instrumentFrame (none)
2021-05-18T04:27:33.261Z,1621312053.261 [CommandLine](IMPORTANT): got command show state
2021-05-18T04:27:33.261Z,1621312053.261 [CommandLine](IMPORTANT): Mission State:

2021-05-18T04:27:33.261Z,1621312053.261 [CommandLine](INFO): Startup->null/0
2021-05-18T04:27:33.262Z,1621312053.262 [CommandLine](INFO): Startup:StartupSatComms->null/0
2021-05-18T04:27:33.262Z,1621312053.262 [CommandLine](INFO): Default->Default:CheckIn/0
2021-05-18T04:27:33.262Z,1621312053.262 [CommandLine](INFO): Default:CheckIn->Default:CheckIn:Read_GPS/0
2021-05-18T04:27:38.480Z,1621312058.480 [CommandLine](IMPORTANT): got command show stack
2021-05-18T04:27:38.480Z,1621312058.480 [CommandLine](IMPORTANT): Behavior Stack:

2021-05-18T04:27:38.480Z,1621312058.480 [Default](IMPORTANT): Priority 0: Default:B.GoToSurface
2021-05-18T04:27:38.480Z,1621312058.480 [Default:CheckIn](IMPORTANT): Priority 1: Default:CheckIn:Read_GPS
2021-05-18T04:27:53.601Z,1621312073.601 [CommandLine](IMPORTANT): got command run ./Missions/lab_range_test.xml
2021-05-18T04:27:53.601Z,1621312073.601 [MissionManager](INFO): Loading Mission: ./Missions/lab_range_test.xml
2021-05-18T04:27:53.625Z,1621312073.625 [MissionManager](INFO): DefineArg lab_range_test.MissionTimeout = 2.000000 min
2021-05-18T04:27:53.628Z,1621312073.628 [MissionManager](INFO): DefineArg lab_range_test.ContactLabel = 50.000000 count
2021-05-18T04:27:53.630Z,1621312073.630 [MissionManager](INFO): DefineArg lab_range_test.TrackingUpdatePeriod = 5.000000 s
2021-05-18T04:27:53.633Z,1621312073.633 [MissionManager](INFO): DefineArg lab_range_test.NumberOfPings = 5.000000 count
2021-05-18T04:27:53.636Z,1621312073.636 [MissionManager](INFO): DefineArg lab_range_test.ContactDepth = nan m
2021-05-18T04:27:53.751Z,1621312073.751 [lab_range_test:B.Wait](DEBUG): Construct Wait.
2021-05-18T04:27:53.754Z,1621312073.754 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Derivation="Tethys/Derivation"
       xmlns:Estimation="Tethys/Estimation"
       xmlns:Guidance="Tethys/Guidance" 
       xmlns:Sensor="Tethys/Sensor"
       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/Derivation http://okeanids.mbari.org/tethys/Xml/Derivation.xsd
                           Tethys/Estimation http://okeanids.mbari.org/tethys/Xml/Estimation.xsd
                           Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                           Tethys/Sensor http://okeanids.mbari.org/tethys/Xml/Sensor.xsd
                           Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                           Tethys/Universal http://okeanids.mbari.org/tethys/Xml/Universal.xsd"
       Id="lab_range_test">

    <Description>
        LAB TEST MISSION - ping remote xponder
    </Description>

    <DefineArg Name="MissionTimeout"><Description>
        Maximum duration of mission
    </Description><Units:minute/><Value>2</Value></DefineArg>

    <DefineArg Name="ContactLabel"><Description>
        The acoustic address of the asset to be tracked
    </Description><Units:count/><Value>50</Value></DefineArg>

    <DefineArg Name="TrackingUpdatePeriod"><Description>
        How long to wait between acoustic queries
    </Description><Units:second/><Value>5</Value></DefineArg>

    <DefineArg Name="NumberOfPings"><Description>
        Number of return pings to request with each acoustic query (more than 1
        will activate oneway mode)
    </Description><Units:count/><Value>5</Value></DefineArg>

    <DefineArg Name="ContactDepth"><Description>
        The acoustic address of the asset to be tracked
    </Description><Units:meter/><Value>NaN</Value></DefineArg>
    

<!-- Missions should always start with a timeout. -->

    <Timeout Duration="MissionTimeout"/>

    <Estimation:Tracking>
        <Parallel/>
        <Setting><Estimation:Tracking.contactDepthSetting/><Arg Name="ContactDepth"/></Setting>
        <Setting><Estimation:Tracking.contactLabelSetting/><Arg Name="ContactLabel"/></Setting>
        <Setting><Estimation:Tracking.numberOfSamplesSetting/><Arg Name="NumberOfPings"/></Setting>
        <Setting><Estimation:Tracking.updatePeriodSetting/><Arg Name="TrackingUpdatePeriod"/></Setting>
    </Estimation:Tracking>

    <Guidance:Wait>
        <Sequence/>
        <Setting><Guidance:Wait.duration/><Arg Name="MissionTimeout"/></Setting>
    </Guidance:Wait>

</Mission>


2021-05-18T04:27:53.757Z,1621312073.757 [CommandLine](IMPORTANT): Running ./Missions/lab_range_test.xml
2021-05-18T04:27:54.090Z,1621312074.090 [Default] Stopped
2021-05-18T04:27:54.090Z,1621312074.090 [Default](DEBUG): Aggregate::uninitialize Default
2021-05-18T04:27:54.090Z,1621312074.090 [Default:B.GoToSurface] Stopped
2021-05-18T04:27:54.090Z,1621312074.090 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2021-05-18T04:27:54.090Z,1621312074.090 [Default:CheckIn] Stopped
2021-05-18T04:27:54.090Z,1621312074.090 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2021-05-18T04:27:54.090Z,1621312074.090 [Default:CheckIn:Read_GPS] Stopped
2021-05-18T04:27:54.091Z,1621312074.091 [MissionManager](IMPORTANT): Started mission lab_range_test
2021-05-18T04:27:54.091Z,1621312074.091 [lab_range_test] Running Loop=1
2021-05-18T04:27:54.091Z,1621312074.091 [lab_range_test](DEBUG): Aggregate::initialize lab_range_test
2021-05-18T04:27:54.091Z,1621312074.091 [lab_range_test:A.] Running Loop=1
2021-05-18T04:27:54.091Z,1621312074.091 [lab_range_test:A.](INFO): Initializing Tracking.
2021-05-18T04:27:54.092Z,1621312074.092 [lab_range_test:B.Wait] Running Loop=1
2021-05-18T04:27:54.092Z,1621312074.092 [lab_range_test:B.Wait](DEBUG): Initialize Wait Component.
2021-05-18T04:27:54.092Z,1621312074.092 [lab_range_test:A.] Running Loop=1
2021-05-18T04:27:54.092Z,1621312074.092 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:27:54.510Z,1621312074.510 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:27:54.905Z,1621312074.905 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:27:55.317Z,1621312075.317 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:27:55.710Z,1621312075.710 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:27:56.104Z,1621312076.104 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:27:56.619Z,1621312076.619 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:27:56.940Z,1621312076.940 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:27:57.405Z,1621312077.405 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:27:57.807Z,1621312077.807 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:27:58.161Z,1621312078.161 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:27:58.541Z,1621312078.541 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:27:58.942Z,1621312078.942 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:27:59.357Z,1621312079.357 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:27:59.358Z,1621312079.358 [lab_range_test:A.](INFO): update period (5.000000 s) has elapsed, querying...
2021-05-18T04:27:59.358Z,1621312079.358 [lab_range_test:A.](INFO): *** querying DAT ***
2021-05-18T04:27:59.740Z,1621312079.740 [DAT](INFO): ****** received valid address query ******
2021-05-18T04:27:59.740Z,1621312079.740 [DAT](INFO): ****** received valid ping request ******
2021-05-18T04:27:59.741Z,1621312079.741 [DAT](INFO): entering command mode
2021-05-18T04:27:59.753Z,1621312079.753 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:00.148Z,1621312080.148 [DAT](INFO): DAT read: UART Wakeup

2021-05-18T04:28:00.149Z,1621312080.149 [DAT](INFO): DAT read: CONNECT 00800 bits/sec 1 of 4, Rate 1/2 CC 12.50ms MGP

2021-05-18T04:28:00.150Z,1621312080.150 [DAT](INFO): commRate: 800
2021-05-18T04:28:00.150Z,1621312080.150 [DAT](INFO): DAT read: 

2021-05-18T04:28:00.151Z,1621312080.151 [DAT](INFO): ****** received valid address query ******
2021-05-18T04:28:00.151Z,1621312080.151 [DAT](INFO): ****** received valid ping request ******
2021-05-18T04:28:00.161Z,1621312080.161 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:00.534Z,1621312080.534 [DAT](INFO): ****** received valid address query ******
2021-05-18T04:28:00.534Z,1621312080.534 [DAT](INFO): ****** received valid ping request ******
2021-05-18T04:28:00.576Z,1621312080.576 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:00.937Z,1621312080.937 [DAT](INFO): ****** received valid address query ******
2021-05-18T04:28:00.937Z,1621312080.937 [DAT](INFO): ****** received valid ping request ******
2021-05-18T04:28:00.949Z,1621312080.949 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:01.352Z,1621312081.352 [DAT](INFO): ****** received valid address query ******
2021-05-18T04:28:01.352Z,1621312081.352 [DAT](INFO): ****** received valid ping request ******
2021-05-18T04:28:01.361Z,1621312081.361 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:01.760Z,1621312081.760 [DAT](INFO): ****** received valid address query ******
2021-05-18T04:28:01.760Z,1621312081.760 [DAT](INFO): ****** received valid ping request ******
2021-05-18T04:28:01.767Z,1621312081.767 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:02.164Z,1621312082.164 [DAT](INFO): ****** received valid address query ******
2021-05-18T04:28:02.164Z,1621312082.164 [DAT](INFO): ****** received valid ping request ******
2021-05-18T04:28:02.164Z,1621312082.164 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:28:02.194Z,1621312082.194 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:02.559Z,1621312082.559 [DAT](INFO): ****** received valid address query ******
2021-05-18T04:28:02.559Z,1621312082.559 [DAT](INFO): ****** received valid ping request ******
2021-05-18T04:28:02.559Z,1621312082.559 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:28:02.566Z,1621312082.566 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:02.958Z,1621312082.958 [DAT](INFO): ****** received valid address query ******
2021-05-18T04:28:02.958Z,1621312082.958 [DAT](INFO): ****** received valid ping request ******
2021-05-18T04:28:02.958Z,1621312082.958 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:28:02.965Z,1621312082.965 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:03.380Z,1621312083.380 [DAT](INFO): ****** received valid address query ******
2021-05-18T04:28:03.380Z,1621312083.380 [DAT](INFO): ****** received valid ping request ******
2021-05-18T04:28:03.380Z,1621312083.380 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:28:03.393Z,1621312083.393 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:03.787Z,1621312083.787 [DAT](INFO): ****** received valid address query ******
2021-05-18T04:28:03.787Z,1621312083.787 [DAT](INFO): ****** received valid ping request ******
2021-05-18T04:28:03.788Z,1621312083.788 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:28:03.801Z,1621312083.801 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:04.180Z,1621312084.180 [DAT](INFO): ****** received valid address query ******
2021-05-18T04:28:04.180Z,1621312084.180 [DAT](INFO): ****** received valid ping request ******
2021-05-18T04:28:04.180Z,1621312084.180 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:28:04.194Z,1621312084.194 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:04.573Z,1621312084.573 [DAT](INFO): ****** received valid address query ******
2021-05-18T04:28:04.574Z,1621312084.574 [DAT](INFO): ****** received valid ping request ******
2021-05-18T04:28:04.574Z,1621312084.574 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:28:04.581Z,1621312084.581 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:04.582Z,1621312084.582 [lab_range_test:A.](INFO): update period (5.000000 s) has elapsed, querying...
2021-05-18T04:28:04.582Z,1621312084.582 [lab_range_test:A.](INFO): *** querying DAT ***
2021-05-18T04:28:04.986Z,1621312084.986 [DAT](INFO): ****** received valid address query ******
2021-05-18T04:28:04.986Z,1621312084.986 [DAT](INFO): ****** received valid ping request ******
2021-05-18T04:28:04.986Z,1621312084.986 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:28:05.017Z,1621312085.017 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:05.381Z,1621312085.381 [DAT](INFO): ****** received valid address query ******
2021-05-18T04:28:05.382Z,1621312085.382 [DAT](INFO): ****** received valid ping request ******
2021-05-18T04:28:05.382Z,1621312085.382 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:28:05.389Z,1621312085.389 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:05.790Z,1621312085.790 [DAT](INFO): ****** received valid address query ******
2021-05-18T04:28:05.790Z,1621312085.790 [DAT](INFO): ****** received valid ping request ******
2021-05-18T04:28:05.790Z,1621312085.790 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:28:05.801Z,1621312085.801 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:06.206Z,1621312086.206 [DAT](INFO): ****** received valid address query ******
2021-05-18T04:28:06.206Z,1621312086.206 [DAT](INFO): ****** received valid ping request ******
2021-05-18T04:28:06.206Z,1621312086.206 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:28:06.272Z,1621312086.272 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:06.616Z,1621312086.616 [DAT](INFO): ****** received valid address query ******
2021-05-18T04:28:06.616Z,1621312086.616 [DAT](INFO): ****** received valid ping request ******
2021-05-18T04:28:06.616Z,1621312086.616 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:28:06.633Z,1621312086.633 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:07.018Z,1621312087.018 [DAT](INFO): ****** received valid address query ******
2021-05-18T04:28:07.018Z,1621312087.018 [DAT](INFO): ****** received valid ping request ******
2021-05-18T04:28:07.018Z,1621312087.018 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:28:07.045Z,1621312087.045 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:07.412Z,1621312087.412 [DAT](INFO): ****** received valid address query ******
2021-05-18T04:28:07.412Z,1621312087.412 [DAT](INFO): ****** received valid ping request ******
2021-05-18T04:28:07.412Z,1621312087.412 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:28:07.457Z,1621312087.457 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:07.809Z,1621312087.809 [DAT](INFO): ****** received valid address query ******
2021-05-18T04:28:07.809Z,1621312087.809 [DAT](INFO): ****** received valid ping request ******
2021-05-18T04:28:07.809Z,1621312087.809 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:28:07.832Z,1621312087.832 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:08.225Z,1621312088.225 [DAT](INFO): ****** received valid address query ******
2021-05-18T04:28:08.225Z,1621312088.225 [DAT](INFO): ****** received valid ping request ******
2021-05-18T04:28:08.226Z,1621312088.226 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:28:08.238Z,1621312088.238 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:08.614Z,1621312088.614 [DAT](INFO): ****** received valid address query ******
2021-05-18T04:28:08.615Z,1621312088.615 [DAT](INFO): ****** received valid ping request ******
2021-05-18T04:28:08.615Z,1621312088.615 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:28:08.656Z,1621312088.656 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:09.017Z,1621312089.017 [DAT](INFO): ****** received valid address query ******
2021-05-18T04:28:09.017Z,1621312089.017 [DAT](INFO): ****** received valid ping request ******
2021-05-18T04:28:09.018Z,1621312089.018 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:28:09.069Z,1621312089.069 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:09.436Z,1621312089.436 [DAT](INFO): ****** received valid address query ******
2021-05-18T04:28:09.436Z,1621312089.436 [DAT](INFO): ****** received valid ping request ******
2021-05-18T04:28:09.436Z,1621312089.436 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:28:09.450Z,1621312089.450 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:09.900Z,1621312089.900 [DAT](INFO): ****** received valid address query ******
2021-05-18T04:28:09.900Z,1621312089.900 [DAT](INFO): ****** received valid ping request ******
2021-05-18T04:28:09.900Z,1621312089.900 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:28:09.908Z,1621312089.908 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:09.908Z,1621312089.908 [lab_range_test:A.](INFO): update period (5.000000 s) has elapsed, querying...
2021-05-18T04:28:09.908Z,1621312089.908 [lab_range_test:A.](INFO): *** querying DAT ***
2021-05-18T04:28:10.276Z,1621312090.276 [DAT](INFO): ****** received valid address query ******
2021-05-18T04:28:10.276Z,1621312090.276 [DAT](INFO): ****** received valid ping request ******
2021-05-18T04:28:10.276Z,1621312090.276 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:28:10.289Z,1621312090.289 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:10.717Z,1621312090.717 [DAT](INFO): ****** received valid address query ******
2021-05-18T04:28:10.717Z,1621312090.717 [DAT](INFO): ****** received valid ping request ******
2021-05-18T04:28:10.717Z,1621312090.717 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:28:10.725Z,1621312090.725 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:11.066Z,1621312091.066 [DAT](INFO): ****** received valid address query ******
2021-05-18T04:28:11.066Z,1621312091.066 [DAT](INFO): ****** received valid ping request ******
2021-05-18T04:28:11.066Z,1621312091.066 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:28:11.120Z,1621312091.120 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:11.465Z,1621312091.465 [DAT](INFO): ****** received valid address query ******
2021-05-18T04:28:11.466Z,1621312091.466 [DAT](INFO): ****** received valid ping request ******
2021-05-18T04:28:11.466Z,1621312091.466 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:28:11.473Z,1621312091.473 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:11.868Z,1621312091.868 [DAT](INFO): ****** received valid address query ******
2021-05-18T04:28:11.868Z,1621312091.868 [DAT](INFO): ****** received valid ping request ******
2021-05-18T04:28:11.868Z,1621312091.868 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:28:11.875Z,1621312091.875 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:12.254Z,1621312092.254 [DAT](INFO): ****** received valid address query ******
2021-05-18T04:28:12.254Z,1621312092.254 [DAT](INFO): ****** received valid ping request ******
2021-05-18T04:28:12.254Z,1621312092.254 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:28:12.265Z,1621312092.265 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:12.664Z,1621312092.664 [DAT](INFO): ****** received valid address query ******
2021-05-18T04:28:12.664Z,1621312092.664 [DAT](INFO): ****** received valid ping request ******
2021-05-18T04:28:12.664Z,1621312092.664 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:28:12.677Z,1621312092.677 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:13.088Z,1621312093.088 [DAT](INFO): ****** received valid address query ******
2021-05-18T04:28:13.088Z,1621312093.088 [DAT](INFO): ****** received valid ping request ******
2021-05-18T04:28:13.088Z,1621312093.088 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:28:13.101Z,1621312093.101 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:13.476Z,1621312093.476 [DAT](INFO): ****** received valid address query ******
2021-05-18T04:28:13.476Z,1621312093.476 [DAT](INFO): ****** received valid ping request ******
2021-05-18T04:28:13.476Z,1621312093.476 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:28:13.489Z,1621312093.489 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:13.865Z,1621312093.865 [DAT](INFO): ****** received valid address query ******
2021-05-18T04:28:13.866Z,1621312093.866 [DAT](INFO): ****** received valid ping request ******
2021-05-18T04:28:13.866Z,1621312093.866 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:28:13.877Z,1621312093.877 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:14.269Z,1621312094.269 [DAT](INFO): ****** received valid address query ******
2021-05-18T04:28:14.269Z,1621312094.269 [DAT](INFO): ****** received valid ping request ******
2021-05-18T04:28:14.269Z,1621312094.269 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:28:14.281Z,1621312094.281 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:14.674Z,1621312094.674 [DAT](INFO): ****** received valid address query ******
2021-05-18T04:28:14.674Z,1621312094.674 [DAT](INFO): ****** received valid ping request ******
2021-05-18T04:28:14.674Z,1621312094.674 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:28:14.692Z,1621312094.692 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:15.077Z,1621312095.077 [DAT](INFO): ****** received valid address query ******
2021-05-18T04:28:15.077Z,1621312095.077 [DAT](INFO): ****** received valid ping request ******
2021-05-18T04:28:15.077Z,1621312095.077 [DAT](DEBUG): checking for command mode acknowledgment
2021-05-18T04:28:15.077Z,1621312095.077 [DAT](FAULT): failed to enter command mode
2021-05-18T04:28:15.093Z,1621312095.093 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:15.094Z,1621312095.094 [lab_range_test:A.](INFO): update period (5.000000 s) has elapsed, querying...
2021-05-18T04:28:15.094Z,1621312095.094 [lab_range_test:A.](INFO): *** querying DAT ***
2021-05-18T04:28:15.502Z,1621312095.502 [DAT](INFO): ****** received valid address query ******
2021-05-18T04:28:15.502Z,1621312095.502 [DAT](INFO): ****** received valid ping request ******
2021-05-18T04:28:15.503Z,1621312095.503 [DAT](INFO): entering command mode
2021-05-18T04:28:15.517Z,1621312095.517 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:15.900Z,1621312095.900 [DAT](INFO): DAT read: user:6>

2021-05-18T04:28:15.901Z,1621312095.901 [DAT](INFO): DAT read: Command '+++' not found

2021-05-18T04:28:15.901Z,1621312095.901 [DAT](INFO): DAT read: Error

2021-05-18T04:28:15.902Z,1621312095.902 [DAT](INFO): ****** received valid address query ******
2021-05-18T04:28:15.902Z,1621312095.902 [DAT](INFO): ****** received valid ping request ******
2021-05-18T04:28:15.902Z,1621312095.902 [DAT](INFO): setting remote address to 0
2021-05-18T04:28:15.976Z,1621312095.976 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:16.300Z,1621312096.300 [DAT](INFO): DAT read: user:7>

2021-05-18T04:28:16.301Z,1621312096.301 [DAT](INFO): DAT read: RemoteAddr      | 0           

2021-05-18T04:28:16.301Z,1621312096.301 [DAT](INFO): set remote address to 0
2021-05-18T04:28:16.302Z,1621312096.302 [DAT](INFO): ****** received valid address query ******
2021-05-18T04:28:16.302Z,1621312096.302 [DAT](INFO): ****** received valid ping request ******
2021-05-18T04:28:16.302Z,1621312096.302 [DAT](INFO): Querying Benthos address 50 with 5 pings in terminal homing one-way mode.
2021-05-18T04:28:16.304Z,1621312096.304 [DAT](INFO): ****** ping requested ******
2021-05-18T04:28:16.317Z,1621312096.317 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:16.693Z,1621312096.693 [DAT](INFO): DAT read: user:8>

2021-05-18T04:28:16.694Z,1621312096.694 [DAT](INFO): DAT read: Tx time:04:27:50.7346

2021-05-18T04:28:16.694Z,1621312096.694 [DAT](INFO): Ping request sent.
2021-05-18T04:28:16.694Z,1621312096.694 [DAT](INFO): transmitted an acoustic signal
2021-05-18T04:28:16.695Z,1621312096.695 [DAT](INFO): publishing transmit ping time
2021-05-18T04:28:16.695Z,1621312096.695 [DAT](INFO): checking for new query: numPingsReceived=0 elapsed TxPingTime=0.001117
2021-05-18T04:28:16.741Z,1621312096.741 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:17.098Z,1621312097.098 [DAT](INFO): checking for new query: numPingsReceived=0 elapsed TxPingTime=0.403578
2021-05-18T04:28:17.109Z,1621312097.109 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:17.506Z,1621312097.506 [DAT](INFO): checking for new query: numPingsReceived=0 elapsed TxPingTime=0.812052
2021-05-18T04:28:17.514Z,1621312097.514 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:17.914Z,1621312097.914 [DAT](INFO): checking for new query: numPingsReceived=0 elapsed TxPingTime=1.219244
2021-05-18T04:28:17.932Z,1621312097.932 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:18.320Z,1621312098.320 [DAT](INFO): checking for new query: numPingsReceived=0 elapsed TxPingTime=1.625999
2021-05-18T04:28:18.348Z,1621312098.348 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:18.732Z,1621312098.732 [DAT](INFO): checking for new query: numPingsReceived=0 elapsed TxPingTime=2.037850
2021-05-18T04:28:18.760Z,1621312098.760 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:19.137Z,1621312099.137 [DAT](INFO): DAT read: Rx Time:04:27:52.8643 

2021-05-18T04:28:19.137Z,1621312099.137 [DAT](INFO): received an acoustic signal
2021-05-18T04:28:19.139Z,1621312099.139 [DAT](INFO): DAT read: Bearing  69.0,  -8.2 (Local)

2021-05-18T04:28:19.139Z,1621312099.139 [DAT](INFO): Local bearing/azimuth received:
 Bearing  69.0,  -8.2 (Local)

2021-05-18T04:28:19.141Z,1621312099.141 [DAT](INFO): DAT read: Range 7 to 50 :     0.3 m (trip time 0.2 ms) speed 0.0

2021-05-18T04:28:19.142Z,1621312099.142 [DAT](ERROR): Read range message, but no direction.
2021-05-18T04:28:19.142Z,1621312099.142 [DAT](INFO): not publishing receive ping time as it could be a packet for anyone
2021-05-18T04:28:19.143Z,1621312099.143 [DAT](INFO): checking for new query: numPingsReceived=0 elapsed TxPingTime=2.449127
2021-05-18T04:28:19.213Z,1621312099.213 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:19.214Z,1621312099.214 [lab_range_test:A.](INFO): direction in vehicle frame: [ 0.000000 forward, 0.000000 starboard, 0.000000 keelward ]
2021-05-18T04:28:19.543Z,1621312099.543 [DAT](INFO): DAT read: 04:27:52.8643 LVL= 32752, 32753, 32754, 32755, AGC= 69, IDX= 177,-0.37, 1.904, 1.581, 1.866, 1.841, PHS= 0.059,-0.216, 0.010, RAW= 140.4,  11.5, CAL= 141.0,   8.2, ROT=  69.0,  -8.2

2021-05-18T04:28:19.545Z,1621312099.545 [DAT](INFO): got valid direction response:
 04:27:52.8643 LVL= 32752, 32753, 32754, 32755, AGC= 69, IDX= 177,-0.37, 1.904, 1.581, 1.866, 1.841, PHS= 0.059,-0.216, 0.010, RAW= 140.4,  11.5, CAL= 141.0,   8.2, ROT=  69.0,  -8.2

2021-05-18T04:28:19.546Z,1621312099.546 [DAT](INFO): DAT read: Rx Time:04:27:53.3644 

2021-05-18T04:28:19.546Z,1621312099.546 [DAT](INFO): received an acoustic signal
2021-05-18T04:28:19.547Z,1621312099.547 [DAT](INFO): DAT read: Bearing  71.4,  -7.2 (Local)

2021-05-18T04:28:19.548Z,1621312099.548 [DAT](INFO): Local bearing/azimuth received:
 Bearing  71.4,  -7.2 (Local)

2021-05-18T04:28:19.550Z,1621312099.550 [DAT](INFO): DAT read: Range 7 to 50 :     0.5 m (trip time 0.3 ms) speed 0.0

2021-05-18T04:28:19.550Z,1621312099.550 [DAT](INFO): Read range and direction messages.
2021-05-18T04:28:19.552Z,1621312099.552 [DAT](INFO): direction in vehicle frame: [ 0.354704 forward, 0.924036 starboard, -0.142629 keelward ]
2021-05-18T04:28:19.553Z,1621312099.553 [DAT](INFO): not publishing receive ping time as it could be a packet for anyone
2021-05-18T04:28:19.553Z,1621312099.553 [DAT](INFO): publishing direction and range info
2021-05-18T04:28:19.557Z,1621312099.557 [DAT](INFO): checking for new query: numPingsReceived=1 elapsed TxPingTime=2.862683
2021-05-18T04:28:19.565Z,1621312099.565 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:19.567Z,1621312099.567 [lab_range_test:A.](INFO): direction in vehicle frame: [ 0.354704 forward, 0.924036 starboard, -0.142629 keelward ]
2021-05-18T04:28:19.567Z,1621312099.567 [lab_range_test:A.](DEBUG): processing response from DAT
2021-05-18T04:28:19.570Z,1621312099.570 [lab_range_test:A.](INFO): rotationFromVehicleToNavigationFrame_ = [ 0.999300,-0.037327,-0.002513;0.037378,0.998994,0.024795;0.001585,-0.024871,0.999689 ]
2021-05-18T04:28:19.570Z,1621312099.570 [lab_range_test:A.](INFO): rangeToContact_ = 0.500000 m
2021-05-18T04:28:19.573Z,1621312099.573 [lab_range_test:A.](INFO): direction in world frame: [ 0.388769 north, 0.913413 east, -0.120565 down ]
2021-05-18T04:28:19.577Z,1621312099.577 [lab_range_test:A.](INFO): relPosInFSK: [ 0.177352 forward, 0.462018 starboard, -0.071314 keelward ]
2021-05-18T04:28:19.577Z,1621312099.577 [lab_range_test:A.](INFO): relPosInNED: [ 0.194384 north, 0.456706 east, -0.060282 down ]
2021-05-18T04:28:19.578Z,1621312099.578 [lab_range_test:A.](DEBUG): Combining 5 samples.
2021-05-18T04:28:19.579Z,1621312099.579 [lab_range_test:A.](DEBUG): Could not read vehicle position; cannot calculate contact position.
2021-05-18T04:28:19.941Z,1621312099.941 [DAT](INFO): DAT read: 04:27:53.3644 LVL= 32752, 32753, 32754, 32755, AGC= 66, IDX= 497,-0.22, 2.229, 1.875, 2.172, 2.148, PHS= 0.077,-0.229, 0.009, RAW= 137.8,  10.3, CAL= 138.6,   7.2, ROT=  71.4,  -7.2

2021-05-18T04:28:19.942Z,1621312099.942 [DAT](INFO): got valid direction response:
 04:27:53.3644 LVL= 32752, 32753, 32754, 32755, AGC= 66, IDX= 497,-0.22, 2.229, 1.875, 2.172, 2.148, PHS= 0.077,-0.229, 0.009, RAW= 137.8,  10.3, CAL= 138.6,   7.2, ROT=  71.4,  -7.2

2021-05-18T04:28:19.943Z,1621312099.943 [DAT](INFO): DAT read: Rx Time:04:27:53.8643 

2021-05-18T04:28:19.943Z,1621312099.943 [DAT](INFO): received an acoustic signal
2021-05-18T04:28:19.944Z,1621312099.944 [DAT](INFO): DAT read: Bearing  69.3,  -8.1 (Local)

2021-05-18T04:28:19.945Z,1621312099.945 [DAT](INFO): Local bearing/azimuth received:
 Bearing  69.3,  -8.1 (Local)

2021-05-18T04:28:19.945Z,1621312099.945 [DAT](INFO): Read direction message, but no range.
2021-05-18T04:28:19.946Z,1621312099.946 [DAT](INFO): direction in vehicle frame: [ 0.316444 forward, 0.940295 starboard, -0.125333 keelward ]
2021-05-18T04:28:19.946Z,1621312099.946 [DAT](INFO): not publishing receive ping time as it could be a packet for anyone
2021-05-18T04:28:19.951Z,1621312099.951 [DAT](INFO): checking for new query: numPingsReceived=1 elapsed TxPingTime=3.256092
2021-05-18T04:28:20.011Z,1621312100.011 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:20.362Z,1621312100.362 [DAT](INFO): DAT read: Range 7 to 50 :     0.3 m (trip time 0.2 ms) speed 0.0

2021-05-18T04:28:20.368Z,1621312100.368 [DAT](INFO): DAT read: 04:27:53.8643 LVL= 32752, 32753, 32754, 32755, AGC= 67, IDX= 496,-0.09, 1.328, 1.018, 1.291, 1.266, PHS= 0.058,-0.204, 0.010, RAW= 140.1,  11.3, CAL= 140.7,   8.1, ROT=  69.3,  -8.1

2021-05-18T04:28:20.369Z,1621312100.369 [DAT](INFO): got valid direction response:
 04:27:53.8643 LVL= 32752, 32753, 32754, 32755, AGC= 67, IDX= 496,-0.09, 1.328, 1.018, 1.291, 1.266, PHS= 0.058,-0.204, 0.010, RAW= 140.1,  11.3, CAL= 140.7,   8.1, ROT=  69.3,  -8.1

2021-05-18T04:28:20.370Z,1621312100.370 [DAT](INFO): Read range and direction messages.
2021-05-18T04:28:20.393Z,1621312100.393 [DAT](INFO): direction in vehicle frame: [ 0.349948 forward, 0.926112 starboard, -0.140901 keelward ]
2021-05-18T04:28:20.394Z,1621312100.394 [DAT](INFO): publishing direction and range info
2021-05-18T04:28:20.405Z,1621312100.405 [DAT](INFO): checking for new query: numPingsReceived=2 elapsed TxPingTime=3.710940
2021-05-18T04:28:20.422Z,1621312100.422 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:20.428Z,1621312100.428 [lab_range_test:A.](INFO): direction in vehicle frame: [ 0.349948 forward, 0.926112 starboard, -0.140901 keelward ]
2021-05-18T04:28:20.428Z,1621312100.428 [lab_range_test:A.](DEBUG): processing response from DAT
2021-05-18T04:28:20.430Z,1621312100.430 [lab_range_test:A.](INFO): rotationFromVehicleToNavigationFrame_ = [ 0.999299,-0.037341,-0.002540;0.037393,0.998994,0.024743;0.001613,-0.024821,0.999691 ]
2021-05-18T04:28:20.431Z,1621312100.431 [lab_range_test:A.](INFO): rangeToContact_ = 0.300000 m
2021-05-18T04:28:20.436Z,1621312100.436 [lab_range_test:A.](INFO): direction in world frame: [ 0.384106 north, 0.915610 east, -0.118832 down ]
2021-05-18T04:28:20.437Z,1621312100.437 [lab_range_test:A.](INFO): relPosInFSK: [ 0.104985 forward, 0.277834 starboard, -0.042270 keelward ]
2021-05-18T04:28:20.437Z,1621312100.437 [lab_range_test:A.](INFO): relPosInNED: [ 0.115232 north, 0.274683 east, -0.035649 down ]
2021-05-18T04:28:20.438Z,1621312100.438 [lab_range_test:A.](DEBUG): Combining 5 samples.
2021-05-18T04:28:20.438Z,1621312100.438 [lab_range_test:A.](DEBUG): Could not read vehicle position; cannot calculate contact position.
2021-05-18T04:28:20.761Z,1621312100.761 [DAT](INFO): DAT read: Rx Time:04:27:54.3643 

2021-05-18T04:28:20.761Z,1621312100.761 [DAT](INFO): received an acoustic signal
2021-05-18T04:28:20.762Z,1621312100.762 [DAT](INFO): DAT read: Bearing  70.9,  -7.1 (Local)

2021-05-18T04:28:20.763Z,1621312100.763 [DAT](INFO): Local bearing/azimuth received:
 Bearing  70.9,  -7.1 (Local)

2021-05-18T04:28:20.765Z,1621312100.765 [DAT](INFO): DAT read: Range 7 to 50 :     0.3 m (trip time 0.2 ms) speed 0.0

2021-05-18T04:28:20.770Z,1621312100.770 [DAT](INFO): DAT read: 04:27:54.3643 LVL= 32752, 32753, 32754, 32755, AGC= 67, IDX= 496, 0.00, 2.368, 2.073, 2.327, 2.302, PHS= 0.062,-0.185, 0.009, RAW= 138.4,  10.2, CAL= 139.1,   7.1, ROT=  70.9,  -7.1

2021-05-18T04:28:20.771Z,1621312100.771 [DAT](INFO): got valid direction response:
 04:27:54.3643 LVL= 32752, 32753, 32754, 32755, AGC= 67, IDX= 496, 0.00, 2.368, 2.073, 2.327, 2.302, PHS= 0.062,-0.185, 0.009, RAW= 138.4,  10.2, CAL= 139.1,   7.1, ROT=  70.9,  -7.1

2021-05-18T04:28:20.772Z,1621312100.772 [DAT](INFO): Read range and direction messages.
2021-05-18T04:28:20.773Z,1621312100.773 [DAT](INFO): direction in vehicle frame: [ 0.324709 forward, 0.937703 starboard, -0.123601 keelward ]
2021-05-18T04:28:20.773Z,1621312100.773 [DAT](INFO): not publishing receive ping time as it could be a packet for anyone
2021-05-18T04:28:20.773Z,1621312100.773 [DAT](INFO): publishing direction and range info
2021-05-18T04:28:20.781Z,1621312100.781 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=4.086697
2021-05-18T04:28:20.815Z,1621312100.815 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:20.816Z,1621312100.816 [lab_range_test:A.](INFO): direction in vehicle frame: [ 0.324709 forward, 0.937703 starboard, -0.123601 keelward ]
2021-05-18T04:28:20.816Z,1621312100.816 [lab_range_test:A.](DEBUG): processing response from DAT
2021-05-18T04:28:20.818Z,1621312100.818 [lab_range_test:A.](INFO): rotationFromVehicleToNavigationFrame_ = [ 0.999322,-0.036729,-0.002553;0.036781,0.999016,0.024785;0.001640,-0.024863,0.999690 ]
2021-05-18T04:28:20.818Z,1621312100.818 [lab_range_test:A.](INFO): rangeToContact_ = 0.300000 m
2021-05-18T04:28:20.827Z,1621312100.827 [lab_range_test:A.](INFO): direction in world frame: [ 0.358776 north, 0.927927 east, -0.101151 down ]
2021-05-18T04:28:20.828Z,1621312100.828 [lab_range_test:A.](INFO): relPosInFSK: [ 0.097413 forward, 0.281311 starboard, -0.037080 keelward ]
2021-05-18T04:28:20.829Z,1621312100.829 [lab_range_test:A.](INFO): relPosInNED: [ 0.107633 north, 0.278378 east, -0.030345 down ]
2021-05-18T04:28:20.829Z,1621312100.829 [lab_range_test:A.](DEBUG): Combining 5 samples.
2021-05-18T04:28:20.829Z,1621312100.829 [lab_range_test:A.](DEBUG): Could not read vehicle position; cannot calculate contact position.
2021-05-18T04:28:21.157Z,1621312101.157 [DAT](INFO): DAT read: Rx Time:04:27:55.2088 

2021-05-18T04:28:21.158Z,1621312101.158 [DAT](INFO): received an acoustic signal
2021-05-18T04:28:21.159Z,1621312101.159 [DAT](INFO): DAT read: Bearing  71.0,  -7.2 (Local)

2021-05-18T04:28:21.160Z,1621312101.160 [DAT](INFO): Local bearing/azimuth received:
 Bearing  71.0,  -7.2 (Local)

2021-05-18T04:28:21.162Z,1621312101.162 [DAT](INFO): DAT read: Range 7 to 50 :   517.2 m (trip time 344.8 ms) speed 0.0

2021-05-18T04:28:21.167Z,1621312101.167 [DAT](INFO): DAT read: 04:27:55.2088 LVL= 32752, 32753, 32754, 32755, AGC= 67, IDX= 495, 0.14, 1.430, 1.155, 1.392, 1.370, PHS= 0.056,-0.171, 0.008, RAW= 138.3,  10.3, CAL= 139.0,   7.2, ROT=  71.0,  -7.2

2021-05-18T04:28:21.168Z,1621312101.168 [DAT](INFO): got valid direction response:
 04:27:55.2088 LVL= 32752, 32753, 32754, 32755, AGC= 67, IDX= 495, 0.14, 1.430, 1.155, 1.392, 1.370, PHS= 0.056,-0.171, 0.008, RAW= 138.3,  10.3, CAL= 139.0,   7.2, ROT=  71.0,  -7.2

2021-05-18T04:28:21.168Z,1621312101.168 [DAT](INFO): Read range and direction messages.
2021-05-18T04:28:21.169Z,1621312101.169 [DAT](INFO): direction in vehicle frame: [ 0.323001 forward, 0.938063 starboard, -0.125333 keelward ]
2021-05-18T04:28:21.169Z,1621312101.169 [DAT](INFO): not publishing receive ping time as it could be a packet for anyone
2021-05-18T04:28:21.170Z,1621312101.170 [DAT](INFO): publishing direction and range info
2021-05-18T04:28:21.173Z,1621312101.173 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=4.478418
2021-05-18T04:28:21.185Z,1621312101.185 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:21.186Z,1621312101.186 [lab_range_test:A.](INFO): direction in vehicle frame: [ 0.323001 forward, 0.938063 starboard, -0.125333 keelward ]
2021-05-18T04:28:21.186Z,1621312101.186 [lab_range_test:A.](DEBUG): processing response from DAT
2021-05-18T04:28:21.189Z,1621312101.189 [lab_range_test:A.](INFO): rotationFromVehicleToNavigationFrame_ = [ 0.999286,-0.037695,-0.002575;0.037747,0.998983,0.024679;0.001642,-0.024759,0.999692 ]
2021-05-18T04:28:21.189Z,1621312101.189 [lab_range_test:A.](INFO): rangeToContact_ = 517.200012 m
2021-05-18T04:28:21.190Z,1621312101.190 [lab_range_test:A.](INFO): direction in world frame: [ 0.357974 north, 0.928036 east, -0.102976 down ]
2021-05-18T04:28:21.191Z,1621312101.191 [lab_range_test:A.](INFO): relPosInFSK: [ 167.056090 forward, 485.166136 starboard, -64.822346 keelward ]
2021-05-18T04:28:21.212Z,1621312101.212 [lab_range_test:A.](INFO): relPosInNED: [ 185.144130 north, 479.980196 east, -53.259041 down ]
2021-05-18T04:28:21.212Z,1621312101.212 [lab_range_test:A.](DEBUG): Combining 5 samples.
2021-05-18T04:28:21.212Z,1621312101.212 [lab_range_test:A.](DEBUG): Could not read vehicle position; cannot calculate contact position.
2021-05-18T04:28:21.546Z,1621312101.546 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=4.852145
2021-05-18T04:28:21.576Z,1621312101.576 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:21.954Z,1621312101.954 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=5.259599
2021-05-18T04:28:21.962Z,1621312101.962 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:22.368Z,1621312102.368 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=5.673891
2021-05-18T04:28:22.405Z,1621312102.405 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:22.856Z,1621312102.856 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=6.161813
2021-05-18T04:28:22.869Z,1621312102.869 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:23.240Z,1621312103.240 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=6.545983
2021-05-18T04:28:23.248Z,1621312103.248 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:23.602Z,1621312103.602 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=6.907211
2021-05-18T04:28:23.625Z,1621312103.625 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:24.003Z,1621312104.003 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=7.308217
2021-05-18T04:28:24.010Z,1621312104.010 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:24.391Z,1621312104.391 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=7.697146
2021-05-18T04:28:24.398Z,1621312104.398 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:24.787Z,1621312104.787 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=8.091535
2021-05-18T04:28:24.796Z,1621312104.796 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:25.177Z,1621312105.177 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=8.483133
2021-05-18T04:28:25.213Z,1621312105.213 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:25.593Z,1621312105.593 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=8.898830
2021-05-18T04:28:25.606Z,1621312105.606 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:26.008Z,1621312106.008 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=9.313836
2021-05-18T04:28:26.021Z,1621312106.021 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:26.412Z,1621312106.412 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=9.717826
2021-05-18T04:28:26.425Z,1621312106.425 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:26.426Z,1621312106.426 [lab_range_test:A.](INFO): update period (5.000000 s) has elapsed, querying...
2021-05-18T04:28:26.426Z,1621312106.426 [lab_range_test:A.](INFO): *** querying DAT ***
2021-05-18T04:28:26.806Z,1621312106.806 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=10.111483
2021-05-18T04:28:26.829Z,1621312106.829 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:27.210Z,1621312107.210 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=10.515215
2021-05-18T04:28:27.217Z,1621312107.217 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:27.614Z,1621312107.614 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=10.919708
2021-05-18T04:28:27.622Z,1621312107.622 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:28.014Z,1621312108.014 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=11.319633
2021-05-18T04:28:28.033Z,1621312108.033 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:28.432Z,1621312108.432 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=11.737391
2021-05-18T04:28:28.445Z,1621312108.445 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:28.832Z,1621312108.832 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=12.137777
2021-05-18T04:28:28.860Z,1621312108.860 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:29.244Z,1621312109.244 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=12.549965
2021-05-18T04:28:29.251Z,1621312109.251 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:29.626Z,1621312109.626 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2021-05-18T04:28:29.645Z,1621312109.645 [BPC1](INFO): Received data from all battery sticks.
2021-05-18T04:28:29.665Z,1621312109.665 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=12.970666
2021-05-18T04:28:29.677Z,1621312109.677 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:30.029Z,1621312110.029 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=13.335065
2021-05-18T04:28:30.041Z,1621312110.041 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:30.434Z,1621312110.434 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=13.739494
2021-05-18T04:28:30.441Z,1621312110.441 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:30.838Z,1621312110.838 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=14.143938
2021-05-18T04:28:30.859Z,1621312110.859 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:31.242Z,1621312111.242 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=14.547408
2021-05-18T04:28:31.269Z,1621312111.269 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:31.656Z,1621312111.656 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=14.961975
2021-05-18T04:28:31.684Z,1621312111.684 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:31.684Z,1621312111.684 [lab_range_test:A.](INFO): update period (5.000000 s) has elapsed, querying...
2021-05-18T04:28:31.684Z,1621312111.684 [lab_range_test:A.](INFO): *** querying DAT ***
2021-05-18T04:28:32.056Z,1621312112.056 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=15.361815
2021-05-18T04:28:32.070Z,1621312112.070 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:32.472Z,1621312112.472 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=15.777843
2021-05-18T04:28:32.485Z,1621312112.485 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:32.854Z,1621312112.854 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=16.159611
2021-05-18T04:28:32.886Z,1621312112.886 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:33.258Z,1621312113.258 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=16.563169
2021-05-18T04:28:33.265Z,1621312113.265 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:33.662Z,1621312113.662 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=16.967936
2021-05-18T04:28:33.677Z,1621312113.677 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:34.070Z,1621312114.070 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=17.375572
2021-05-18T04:28:34.089Z,1621312114.089 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:34.488Z,1621312114.488 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=17.793257
2021-05-18T04:28:34.501Z,1621312114.501 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:34.888Z,1621312114.888 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=18.193752
2021-05-18T04:28:34.914Z,1621312114.914 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:35.295Z,1621312115.295 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=18.600849
2021-05-18T04:28:35.304Z,1621312115.304 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:35.691Z,1621312115.691 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=18.996490
2021-05-18T04:28:35.698Z,1621312115.698 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:36.089Z,1621312116.089 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=19.395109
2021-05-18T04:28:36.116Z,1621312116.116 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:36.490Z,1621312116.490 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=19.795374
2021-05-18T04:28:36.504Z,1621312116.504 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:36.894Z,1621312116.894 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=20.199718
2021-05-18T04:28:36.908Z,1621312116.908 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:36.909Z,1621312116.909 [lab_range_test:A.](INFO): update period (5.000000 s) has elapsed, querying...
2021-05-18T04:28:36.909Z,1621312116.909 [lab_range_test:A.](INFO): *** querying DAT ***
2021-05-18T04:28:36.926Z,1621312116.926 [CBIT](INFO): Clearing failed state for component AMEcho
2021-05-18T04:28:36.926Z,1621312116.926 [AMEcho] No Fault, FailCount= 3
2021-05-18T04:28:37.309Z,1621312117.309 [AMEcho](INFO): Powering up.
2021-05-18T04:28:37.328Z,1621312117.328 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=20.633549
2021-05-18T04:28:37.345Z,1621312117.345 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:37.720Z,1621312117.720 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=21.025433
2021-05-18T04:28:37.744Z,1621312117.744 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:38.121Z,1621312118.121 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=21.426210
2021-05-18T04:28:38.165Z,1621312118.165 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:38.532Z,1621312118.532 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=21.838108
2021-05-18T04:28:38.546Z,1621312118.546 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:38.914Z,1621312118.914 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=22.219824
2021-05-18T04:28:38.949Z,1621312118.949 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:39.352Z,1621312119.352 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=22.657024
2021-05-18T04:28:39.399Z,1621312119.399 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:39.723Z,1621312119.723 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=23.028219
2021-05-18T04:28:39.741Z,1621312119.741 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:40.137Z,1621312120.137 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=23.442173
2021-05-18T04:28:40.144Z,1621312120.144 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:40.541Z,1621312120.541 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=23.846565
2021-05-18T04:28:40.570Z,1621312120.570 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:40.949Z,1621312120.949 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=24.254242
2021-05-18T04:28:40.961Z,1621312120.961 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:41.349Z,1621312121.349 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=24.654589
2021-05-18T04:28:41.361Z,1621312121.361 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:41.750Z,1621312121.750 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=25.056078
2021-05-18T04:28:41.774Z,1621312121.774 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:42.151Z,1621312122.151 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=25.456898
2021-05-18T04:28:42.158Z,1621312122.158 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:42.179Z,1621312122.179 [lab_range_test:A.](INFO): update period (5.000000 s) has elapsed, querying...
2021-05-18T04:28:42.179Z,1621312122.179 [lab_range_test:A.](INFO): *** querying DAT ***
2021-05-18T04:28:42.551Z,1621312122.551 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=25.856815
2021-05-18T04:28:42.565Z,1621312122.565 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:42.954Z,1621312122.954 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=26.259930
2021-05-18T04:28:42.965Z,1621312122.965 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:43.373Z,1621312123.373 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=26.678478
2021-05-18T04:28:43.385Z,1621312123.385 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:43.781Z,1621312123.781 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=27.086506
2021-05-18T04:28:43.793Z,1621312123.793 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:44.177Z,1621312124.177 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=27.482613
2021-05-18T04:28:44.209Z,1621312124.209 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:44.575Z,1621312124.575 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=27.880363
2021-05-18T04:28:44.582Z,1621312124.582 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:44.978Z,1621312124.978 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=28.284103
2021-05-18T04:28:45.002Z,1621312125.002 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:45.393Z,1621312125.393 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=28.698702
2021-05-18T04:28:45.417Z,1621312125.417 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:45.801Z,1621312125.801 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=29.106245
2021-05-18T04:28:45.825Z,1621312125.825 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:46.197Z,1621312126.197 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=29.502485
2021-05-18T04:28:46.209Z,1621312126.209 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:46.599Z,1621312126.599 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=29.904192
2021-05-18T04:28:46.606Z,1621312126.606 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:47.001Z,1621312127.001 [DAT](INFO): ****** received valid address query ******
2021-05-18T04:28:47.001Z,1621312127.001 [DAT](INFO): ****** received valid ping request ******
2021-05-18T04:28:47.002Z,1621312127.002 [DAT](INFO): Querying Benthos address 50 with 5 pings in terminal homing one-way mode.
2021-05-18T04:28:47.011Z,1621312127.011 [DAT](INFO): ****** ping requested ******
2021-05-18T04:28:47.034Z,1621312127.034 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:47.399Z,1621312127.399 [DAT](INFO): DAT read: user:9>

2021-05-18T04:28:47.400Z,1621312127.400 [DAT](INFO): DAT read: Tx time:04:28:21.7790

2021-05-18T04:28:47.400Z,1621312127.400 [DAT](INFO): Ping request sent.
2021-05-18T04:28:47.400Z,1621312127.400 [DAT](INFO): transmitted an acoustic signal
2021-05-18T04:28:47.400Z,1621312127.400 [DAT](INFO): publishing transmit ping time
2021-05-18T04:28:47.401Z,1621312127.401 [DAT](INFO): checking for new query: numPingsReceived=0 elapsed TxPingTime=0.001002
2021-05-18T04:28:47.413Z,1621312127.413 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:47.414Z,1621312127.414 [lab_range_test:A.](INFO): update period (5.000000 s) has elapsed, querying...
2021-05-18T04:28:47.414Z,1621312127.414 [lab_range_test:A.](INFO): *** querying DAT ***
2021-05-18T04:28:47.807Z,1621312127.807 [DAT](INFO): checking for new query: numPingsReceived=0 elapsed TxPingTime=0.407058
2021-05-18T04:28:47.850Z,1621312127.850 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:48.207Z,1621312128.207 [DAT](INFO): checking for new query: numPingsReceived=0 elapsed TxPingTime=0.806611
2021-05-18T04:28:48.214Z,1621312128.214 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:48.625Z,1621312128.625 [DAT](INFO): checking for new query: numPingsReceived=0 elapsed TxPingTime=1.224797
2021-05-18T04:28:48.637Z,1621312128.637 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:49.037Z,1621312129.037 [DAT](INFO): checking for new query: numPingsReceived=0 elapsed TxPingTime=1.637235
2021-05-18T04:28:49.045Z,1621312129.045 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:49.429Z,1621312129.429 [DAT](INFO): checking for new query: numPingsReceived=0 elapsed TxPingTime=2.028598
2021-05-18T04:28:49.454Z,1621312129.454 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:49.832Z,1621312129.832 [DAT](INFO): DAT read: Rx Time:04:28:23.9086 

2021-05-18T04:28:49.832Z,1621312129.832 [DAT](INFO): received an acoustic signal
2021-05-18T04:28:49.834Z,1621312129.834 [DAT](INFO): DAT read: Bearing  72.5,  -6.0 (Local)

2021-05-18T04:28:49.834Z,1621312129.834 [DAT](INFO): Local bearing/azimuth received:
 Bearing  72.5,  -6.0 (Local)

2021-05-18T04:28:49.836Z,1621312129.836 [DAT](INFO): DAT read: Range 7 to 50 :     0.3 m (trip time 0.2 ms) speed 0.0

2021-05-18T04:28:49.837Z,1621312129.837 [DAT](ERROR): Read range message, but no direction.
2021-05-18T04:28:49.837Z,1621312129.837 [DAT](INFO): not publishing receive ping time as it could be a packet for anyone
2021-05-18T04:28:49.838Z,1621312129.838 [DAT](INFO): checking for new query: numPingsReceived=0 elapsed TxPingTime=2.438399
2021-05-18T04:28:49.848Z,1621312129.848 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:49.849Z,1621312129.849 [lab_range_test:A.](INFO): direction in vehicle frame: [ 0.323001 forward, 0.938063 starboard, -0.125333 keelward ]
2021-05-18T04:28:49.849Z,1621312129.849 [lab_range_test:A.](DEBUG): processing response from DAT
2021-05-18T04:28:49.892Z,1621312129.892 [lab_range_test:A.](INFO): rotationFromVehicleToNavigationFrame_ = [ 0.999372,-0.035340,-0.002617;0.035395,0.999061,0.024968;0.001732,-0.025045,0.999685 ]
2021-05-18T04:28:49.892Z,1621312129.892 [lab_range_test:A.](INFO): rangeToContact_ = 0.300000 m
2021-05-18T04:28:49.893Z,1621312129.893 [lab_range_test:A.](INFO): direction in world frame: [ 0.355783 north, 0.928906 east, -0.102718 down ]
2021-05-18T04:28:49.894Z,1621312129.894 [lab_range_test:A.](INFO): relPosInFSK: [ 0.096900 forward, 0.281419 starboard, -0.037600 keelward ]
2021-05-18T04:28:49.894Z,1621312129.894 [lab_range_test:A.](INFO): relPosInNED: [ 0.106735 north, 0.278672 east, -0.030815 down ]
2021-05-18T04:28:49.903Z,1621312129.903 [lab_range_test:A.](DEBUG): Combining 5 samples.
2021-05-18T04:28:49.903Z,1621312129.903 [lab_range_test:A.](DEBUG): Could not read vehicle position; cannot calculate contact position.
2021-05-18T04:28:50.239Z,1621312130.239 [DAT](INFO): DAT read: 04:28:23.9086 LVL= 32752, 32753, 32754, 32755, AGC= 67, IDX= 480, 0.13, 2.381, 2.097, 2.335, 2.311, PHS= 0.066,-0.170, 0.009, RAW= 136.6,   9.0, CAL= 137.5,   6.0, ROT=  72.5,  -6.0

2021-05-18T04:28:50.241Z,1621312130.241 [DAT](INFO): got valid direction response:
 04:28:23.9086 LVL= 32752, 32753, 32754, 32755, AGC= 67, IDX= 480, 0.13, 2.381, 2.097, 2.335, 2.311, PHS= 0.066,-0.170, 0.009, RAW= 136.6,   9.0, CAL= 137.5,   6.0, ROT=  72.5,  -6.0

2021-05-18T04:28:50.242Z,1621312130.242 [DAT](INFO): DAT read: Rx Time:04:28:24.4085 

2021-05-18T04:28:50.242Z,1621312130.242 [DAT](INFO): received an acoustic signal
2021-05-18T04:28:50.244Z,1621312130.244 [DAT](INFO): DAT read: Bearing  72.2,  -6.7 (Local)

2021-05-18T04:28:50.244Z,1621312130.244 [DAT](INFO): Local bearing/azimuth received:
 Bearing  72.2,  -6.7 (Local)

2021-05-18T04:28:50.246Z,1621312130.246 [DAT](INFO): DAT read: Range 7 to 50 :     0.2 m (trip time 0.1 ms) speed 0.0

2021-05-18T04:28:50.246Z,1621312130.246 [DAT](INFO): Read range and direction messages.
2021-05-18T04:28:50.248Z,1621312130.248 [DAT](INFO): direction in vehicle frame: [ 0.299059 forward, 0.948492 starboard, -0.104528 keelward ]
2021-05-18T04:28:50.248Z,1621312130.248 [DAT](INFO): not publishing receive ping time as it could be a packet for anyone
2021-05-18T04:28:50.248Z,1621312130.248 [DAT](INFO): publishing direction and range info
2021-05-18T04:28:50.252Z,1621312130.252 [DAT](INFO): checking for new query: numPingsReceived=1 elapsed TxPingTime=2.852440
2021-05-18T04:28:50.261Z,1621312130.261 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:50.263Z,1621312130.263 [lab_range_test:A.](INFO): direction in vehicle frame: [ 0.299059 forward, 0.948492 starboard, -0.104528 keelward ]
2021-05-18T04:28:50.263Z,1621312130.263 [lab_range_test:A.](DEBUG): processing response from DAT
2021-05-18T04:28:50.266Z,1621312130.266 [lab_range_test:A.](INFO): rotationFromVehicleToNavigationFrame_ = [ 0.999311,-0.037024,-0.002618;0.037078,0.999004,0.024829;0.001697,-0.024909,0.999688 ]
2021-05-18T04:28:50.266Z,1621312130.266 [lab_range_test:A.](INFO): rangeToContact_ = 0.200000 m
2021-05-18T04:28:50.267Z,1621312130.267 [lab_range_test:A.](INFO): direction in world frame: [ 0.333843 north, 0.939079 east, -0.081728 down ]
2021-05-18T04:28:50.268Z,1621312130.268 [lab_range_test:A.](INFO): relPosInFSK: [ 0.059812 forward, 0.189698 starboard, -0.020906 keelward ]
2021-05-18T04:28:50.269Z,1621312130.269 [lab_range_test:A.](INFO): relPosInNED: [ 0.066769 north, 0.187816 east, -0.016346 down ]
2021-05-18T04:28:50.269Z,1621312130.269 [lab_range_test:A.](DEBUG): Combining 5 samples.
2021-05-18T04:28:50.269Z,1621312130.269 [lab_range_test:A.](DEBUG): Could not read vehicle position; cannot calculate contact position.
2021-05-18T04:28:50.654Z,1621312130.654 [DAT](INFO): DAT read: 04:28:24.4085 LVL= 32752, 32753, 32754, 32755, AGC= 67, IDX= 495, 0.31, 1.559, 1.306, 1.522, 1.501, PHS= 0.054,-0.150, 0.006, RAW= 137.0,   9.8, CAL= 137.8,   6.7, ROT=  72.2,  -6.7

2021-05-18T04:28:50.656Z,1621312130.656 [DAT](INFO): got valid direction response:
 04:28:24.4085 LVL= 32752, 32753, 32754, 32755, AGC= 67, IDX= 495, 0.31, 1.559, 1.306, 1.522, 1.501, PHS= 0.054,-0.150, 0.006, RAW= 137.0,   9.8, CAL= 137.8,   6.7, ROT=  72.2,  -6.7

2021-05-18T04:28:50.657Z,1621312130.657 [DAT](INFO): DAT read: Rx Time:04:28:24.9085 

2021-05-18T04:28:50.657Z,1621312130.657 [DAT](INFO): received an acoustic signal
2021-05-18T04:28:50.658Z,1621312130.658 [DAT](INFO): DAT read: Bearing 117.1,  14.0 (Local)

2021-05-18T04:28:50.658Z,1621312130.658 [DAT](INFO): Local bearing/azimuth received:
 Bearing 117.1,  14.0 (Local)

2021-05-18T04:28:50.658Z,1621312130.658 [DAT](INFO): Read direction message, but no range.
2021-05-18T04:28:50.660Z,1621312130.660 [DAT](INFO): direction in vehicle frame: [ 0.303608 forward, 0.945627 starboard, -0.116671 keelward ]
2021-05-18T04:28:50.661Z,1621312130.661 [DAT](INFO): not publishing receive ping time as it could be a packet for anyone
2021-05-18T04:28:50.664Z,1621312130.664 [DAT](INFO): checking for new query: numPingsReceived=1 elapsed TxPingTime=3.264323
2021-05-18T04:28:50.673Z,1621312130.673 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:51.036Z,1621312131.036 [DAT](INFO): DAT read: Range 7 to 50 :     0.2 m (trip time 0.1 ms) speed 0.0

2021-05-18T04:28:51.041Z,1621312131.041 [DAT](INFO): DAT read: 04:28:24.9085 LVL= 32752, 32753, 32754, 32755, AGC= 67, IDX= 512,-0.46, 0.752,-2.172,-2.004,-1.668, PHS= 2.416,-0.459,-0.350, RAW=  91.9, -11.4, CAL=  92.9, -14.0, ROT= 117.1,  14.0

2021-05-18T04:28:51.042Z,1621312131.042 [DAT](INFO): got valid direction response:
 04:28:24.9085 LVL= 32752, 32753, 32754, 32755, AGC= 67, IDX= 512,-0.46, 0.752,-2.172,-2.004,-1.668, PHS= 2.416,-0.459,-0.350, RAW=  91.9, -11.4, CAL=  92.9, -14.0, ROT= 117.1,  14.0

2021-05-18T04:28:51.043Z,1621312131.043 [DAT](INFO): Read range and direction messages.
2021-05-18T04:28:51.044Z,1621312131.044 [DAT](INFO): direction in vehicle frame: [ -0.442013 forward, 0.863770 starboard, 0.241922 keelward ]
2021-05-18T04:28:51.044Z,1621312131.044 [DAT](INFO): publishing direction and range info
2021-05-18T04:28:51.048Z,1621312131.048 [DAT](INFO): checking for new query: numPingsReceived=2 elapsed TxPingTime=3.647665
2021-05-18T04:28:51.057Z,1621312131.057 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:51.059Z,1621312131.059 [lab_range_test:A.](INFO): direction in vehicle frame: [ -0.442013 forward, 0.863770 starboard, 0.241922 keelward ]
2021-05-18T04:28:51.059Z,1621312131.059 [lab_range_test:A.](DEBUG): processing response from DAT
2021-05-18T04:28:51.061Z,1621312131.061 [lab_range_test:A.](INFO): rotationFromVehicleToNavigationFrame_ = [ 0.999306,-0.037154,-0.002610;0.037207,0.999000,0.024788;0.001687,-0.024868,0.999689 ]
2021-05-18T04:28:51.062Z,1621312131.062 [lab_range_test:A.](INFO): rangeToContact_ = 0.200000 m
2021-05-18T04:28:51.063Z,1621312131.063 [lab_range_test:A.](INFO): direction in world frame: [ -0.409160 north, 0.873313 east, 0.264411 down ]
2021-05-18T04:28:51.064Z,1621312131.064 [lab_range_test:A.](INFO): relPosInFSK: [ -0.088403 forward, 0.172754 starboard, 0.048384 keelward ]
2021-05-18T04:28:51.065Z,1621312131.065 [lab_range_test:A.](INFO): relPosInNED: [ -0.081832 north, 0.174663 east, 0.052882 down ]
2021-05-18T04:28:51.065Z,1621312131.065 [lab_range_test:A.](DEBUG): Combining 5 samples.
2021-05-18T04:28:51.065Z,1621312131.065 [lab_range_test:A.](DEBUG): Could not read vehicle position; cannot calculate contact position.
2021-05-18T04:28:51.453Z,1621312131.453 [DAT](INFO): DAT read: Rx Time:04:28:25.4084 

2021-05-18T04:28:51.454Z,1621312131.454 [DAT](INFO): received an acoustic signal
2021-05-18T04:28:51.456Z,1621312131.456 [DAT](INFO): DAT read: Bearing  68.7,  -9.4 (Local)

2021-05-18T04:28:51.456Z,1621312131.456 [DAT](INFO): Local bearing/azimuth received:
 Bearing  68.7,  -9.4 (Local)

2021-05-18T04:28:51.458Z,1621312131.458 [DAT](INFO): DAT read: Range 7 to 50 :     0.0 m (trip time 0.0 ms) speed 0.0

2021-05-18T04:28:51.459Z,1621312131.459 [DAT](INFO): unknown deviceResponse_: Range 7 to 50 :     0.0 m (trip time 0.0 ms) speed 0.0

2021-05-18T04:28:51.463Z,1621312131.463 [DAT](INFO): DAT read: 04:28:25.4084 LVL= 32752, 32753, 32754, 32755, AGC= 67, IDX= 511,-0.26,-1.638,-1.950,-1.672,-1.693, PHS= 0.051,-0.213, 0.006, RAW= 140.8,  12.7, CAL= 141.3,   9.4, ROT=  68.7,  -9.4

2021-05-18T04:28:51.464Z,1621312131.464 [DAT](INFO): got valid direction response:
 04:28:25.4084 LVL= 32752, 32753, 32754, 32755, AGC= 67, IDX= 511,-0.26,-1.638,-1.950,-1.672,-1.693, PHS= 0.051,-0.213, 0.006, RAW= 140.8,  12.7, CAL= 141.3,   9.4, ROT=  68.7,  -9.4

2021-05-18T04:28:51.465Z,1621312131.465 [DAT](INFO): Read direction message, but no range.
2021-05-18T04:28:51.466Z,1621312131.466 [DAT](INFO): direction in vehicle frame: [ 0.358374 forward, 0.919181 starboard, -0.163326 keelward ]
2021-05-18T04:28:51.466Z,1621312131.466 [DAT](INFO): not publishing receive ping time as it could be a packet for anyone
2021-05-18T04:28:51.469Z,1621312131.469 [DAT](INFO): checking for new query: numPingsReceived=2 elapsed TxPingTime=4.069071
2021-05-18T04:28:51.482Z,1621312131.482 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:51.866Z,1621312131.866 [DAT](INFO): DAT read: Rx Time:04:28:25.9085 

2021-05-18T04:28:51.866Z,1621312131.866 [DAT](INFO): received an acoustic signal
2021-05-18T04:28:51.868Z,1621312131.868 [DAT](INFO): DAT read: Bearing  78.3,  -5.5 (Local)

2021-05-18T04:28:51.868Z,1621312131.868 [DAT](INFO): Local bearing/azimuth received:
 Bearing  78.3,  -5.5 (Local)

2021-05-18T04:28:51.870Z,1621312131.870 [DAT](INFO): DAT read: Range 7 to 50 :     0.2 m (trip time 0.1 ms) speed 0.0

2021-05-18T04:28:51.875Z,1621312131.875 [DAT](INFO): DAT read: 04:28:25.9085 LVL= 32752, 32753, 32754, 32755, AGC= 70, IDX=   0, 0.65,-1.982,-2.776,-2.229,-2.234, PHS= 0.248,-0.499,-0.010, RAW= 130.1,   8.0, CAL= 131.7,   5.5, ROT=  78.3,  -5.5

2021-05-18T04:28:51.876Z,1621312131.876 [DAT](INFO): got valid direction response:
 04:28:25.9085 LVL= 32752, 32753, 32754, 32755, AGC= 70, IDX=   0, 0.65,-1.982,-2.776,-2.229,-2.234, PHS= 0.248,-0.499,-0.010, RAW= 130.1,   8.0, CAL= 131.7,   5.5, ROT=  78.3,  -5.5

2021-05-18T04:28:51.876Z,1621312131.876 [DAT](INFO): Read range and direction messages.
2021-05-18T04:28:51.877Z,1621312131.877 [DAT](INFO): direction in vehicle frame: [ 0.201854 forward, 0.974715 starboard, -0.095846 keelward ]
2021-05-18T04:28:51.877Z,1621312131.877 [DAT](INFO): not publishing receive ping time as it could be a packet for anyone
2021-05-18T04:28:51.877Z,1621312131.877 [DAT](INFO): publishing direction and range info
2021-05-18T04:28:51.881Z,1621312131.881 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=4.480662
2021-05-18T04:28:51.889Z,1621312131.889 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:51.890Z,1621312131.890 [lab_range_test:A.](INFO): direction in vehicle frame: [ 0.201854 forward, 0.974715 starboard, -0.095846 keelward ]
2021-05-18T04:28:51.890Z,1621312131.890 [lab_range_test:A.](DEBUG): processing response from DAT
2021-05-18T04:28:51.892Z,1621312131.892 [lab_range_test:A.](INFO): rotationFromVehicleToNavigationFrame_ = [ 0.999357,-0.035756,-0.002519;0.035808,0.999047,0.024958;0.001624,-0.025032,0.999685 ]
2021-05-18T04:28:51.893Z,1621312131.893 [lab_range_test:A.](INFO): rangeToContact_ = 0.200000 m
2021-05-18T04:28:51.893Z,1621312131.893 [lab_range_test:A.](INFO): direction in world frame: [ 0.236471 north, 0.968967 east, -0.071997 down ]
2021-05-18T04:28:51.894Z,1621312131.894 [lab_range_test:A.](INFO): relPosInFSK: [ 0.040371 forward, 0.194943 starboard, -0.019169 keelward ]
2021-05-18T04:28:51.895Z,1621312131.895 [lab_range_test:A.](INFO): relPosInNED: [ 0.047294 north, 0.193793 east, -0.014399 down ]
2021-05-18T04:28:51.895Z,1621312131.895 [lab_range_test:A.](DEBUG): Combining 5 samples.
2021-05-18T04:28:51.896Z,1621312131.896 [lab_range_test:A.](DEBUG): Could not read vehicle position; cannot calculate contact position.
2021-05-18T04:28:52.257Z,1621312132.257 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=4.856808
2021-05-18T04:28:52.285Z,1621312132.285 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:52.651Z,1621312132.651 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=5.250722
2021-05-18T04:28:52.658Z,1621312132.658 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:53.064Z,1621312133.064 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=5.663747
2021-05-18T04:28:53.071Z,1621312133.071 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:53.459Z,1621312133.459 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=6.058641
2021-05-18T04:28:53.493Z,1621312133.493 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:53.872Z,1621312133.872 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=6.471495
2021-05-18T04:28:53.879Z,1621312133.879 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:54.266Z,1621312134.266 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=6.866011
2021-05-18T04:28:54.277Z,1621312134.277 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:54.685Z,1621312134.685 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=7.285012
2021-05-18T04:28:54.697Z,1621312134.697 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:55.093Z,1621312135.093 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=7.693339
2021-05-18T04:28:55.101Z,1621312135.101 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:55.489Z,1621312135.489 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=8.088640
2021-05-18T04:28:55.520Z,1621312135.520 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:55.887Z,1621312135.887 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=8.486748
2021-05-18T04:28:55.894Z,1621312135.894 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:56.291Z,1621312136.291 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=8.890486
2021-05-18T04:28:56.315Z,1621312136.315 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:56.691Z,1621312136.691 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=9.290943
2021-05-18T04:28:56.726Z,1621312136.726 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:57.098Z,1621312137.098 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=9.698440
2021-05-18T04:28:57.106Z,1621312137.106 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:57.106Z,1621312137.106 [lab_range_test:A.](INFO): update period (5.000000 s) has elapsed, querying...
2021-05-18T04:28:57.106Z,1621312137.106 [lab_range_test:A.](INFO): *** querying DAT ***
2021-05-18T04:28:57.509Z,1621312137.509 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=10.108846
2021-05-18T04:28:57.521Z,1621312137.521 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:57.929Z,1621312137.929 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=10.528980
2021-05-18T04:28:57.941Z,1621312137.941 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:58.317Z,1621312138.317 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=10.916802
2021-05-18T04:28:58.345Z,1621312138.345 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:58.714Z,1621312138.714 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=11.314389
2021-05-18T04:28:58.722Z,1621312138.722 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:59.115Z,1621312139.115 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=11.714481
2021-05-18T04:28:59.129Z,1621312139.129 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:59.530Z,1621312139.530 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=12.126798
2021-05-18T04:28:59.538Z,1621312139.538 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:28:59.923Z,1621312139.923 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=12.522832
2021-05-18T04:28:59.957Z,1621312139.957 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:00.337Z,1621312140.337 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=12.936607
2021-05-18T04:29:00.349Z,1621312140.349 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:00.749Z,1621312140.749 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=13.348735
2021-05-18T04:29:00.761Z,1621312140.761 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:01.149Z,1621312141.149 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=13.749308
2021-05-18T04:29:01.157Z,1621312141.157 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:01.539Z,1621312141.539 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=14.138709
2021-05-18T04:29:01.568Z,1621312141.568 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:01.943Z,1621312141.943 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=14.542533
2021-05-18T04:29:01.950Z,1621312141.950 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:02.357Z,1621312142.357 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=14.956873
2021-05-18T04:29:02.370Z,1621312142.370 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:02.370Z,1621312142.370 [lab_range_test:A.](INFO): update period (5.000000 s) has elapsed, querying...
2021-05-18T04:29:02.371Z,1621312142.371 [lab_range_test:A.](INFO): *** querying DAT ***
2021-05-18T04:29:02.769Z,1621312142.769 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=15.368528
2021-05-18T04:29:02.781Z,1621312142.781 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:03.172Z,1621312143.172 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=15.771603
2021-05-18T04:29:03.185Z,1621312143.185 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:03.559Z,1621312143.559 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=16.159185
2021-05-18T04:29:03.566Z,1621312143.566 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:03.962Z,1621312143.962 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=16.562441
2021-05-18T04:29:03.977Z,1621312143.977 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:04.389Z,1621312144.389 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=16.988821
2021-05-18T04:29:04.405Z,1621312144.405 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:04.793Z,1621312144.793 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=17.392941
2021-05-18T04:29:04.805Z,1621312144.805 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:05.189Z,1621312145.189 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=17.789017
2021-05-18T04:29:05.221Z,1621312145.221 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:05.582Z,1621312145.582 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=18.182062
2021-05-18T04:29:05.589Z,1621312145.589 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:05.987Z,1621312145.987 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=18.587042
2021-05-18T04:29:06.011Z,1621312146.011 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:06.387Z,1621312146.387 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=18.986443
2021-05-18T04:29:06.416Z,1621312146.416 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:06.799Z,1621312146.799 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=19.399164
2021-05-18T04:29:06.810Z,1621312146.810 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:07.195Z,1621312147.195 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=19.795115
2021-05-18T04:29:07.210Z,1621312147.210 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:07.613Z,1621312147.613 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=20.212687
2021-05-18T04:29:07.629Z,1621312147.629 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:07.629Z,1621312147.629 [lab_range_test:A.](INFO): update period (5.000000 s) has elapsed, querying...
2021-05-18T04:29:07.629Z,1621312147.629 [lab_range_test:A.](INFO): *** querying DAT ***
2021-05-18T04:29:08.017Z,1621312148.017 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=20.617096
2021-05-18T04:29:08.033Z,1621312148.033 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:08.417Z,1621312148.417 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=21.016796
2021-05-18T04:29:08.460Z,1621312148.460 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:08.810Z,1621312148.810 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=21.409800
2021-05-18T04:29:08.825Z,1621312148.825 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:09.214Z,1621312149.214 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=21.814281
2021-05-18T04:29:09.236Z,1621312149.236 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:09.628Z,1621312149.628 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=22.228397
2021-05-18T04:29:09.642Z,1621312149.642 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:10.022Z,1621312150.022 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=22.622427
2021-05-18T04:29:10.060Z,1621312150.060 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:10.437Z,1621312150.437 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=23.036823
2021-05-18T04:29:10.449Z,1621312150.449 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:10.849Z,1621312150.849 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=23.449415
2021-05-18T04:29:10.857Z,1621312150.857 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:11.249Z,1621312151.249 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=23.848656
2021-05-18T04:29:11.261Z,1621312151.261 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:11.638Z,1621312151.638 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=24.238131
2021-05-18T04:29:11.666Z,1621312151.666 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:12.047Z,1621312152.047 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=24.646772
2021-05-18T04:29:12.054Z,1621312152.054 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:12.446Z,1621312152.446 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=25.046040
2021-05-18T04:29:12.458Z,1621312152.458 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:12.863Z,1621312152.863 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=25.463148
2021-05-18T04:29:12.877Z,1621312152.877 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:12.878Z,1621312152.878 [lab_range_test:A.](INFO): update period (5.000000 s) has elapsed, querying...
2021-05-18T04:29:12.878Z,1621312152.878 [lab_range_test:A.](INFO): *** querying DAT ***
2021-05-18T04:29:13.254Z,1621312153.254 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=25.854418
2021-05-18T04:29:13.290Z,1621312153.290 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:13.669Z,1621312153.669 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=26.268604
2021-05-18T04:29:13.681Z,1621312153.681 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:14.077Z,1621312154.077 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=26.677181
2021-05-18T04:29:14.089Z,1621312154.089 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:14.481Z,1621312154.481 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=27.080898
2021-05-18T04:29:14.488Z,1621312154.488 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:14.875Z,1621312154.875 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=27.474468
2021-05-18T04:29:14.902Z,1621312154.902 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:15.278Z,1621312155.278 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=27.878040
2021-05-18T04:29:15.285Z,1621312155.285 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:15.683Z,1621312155.683 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=28.283203
2021-05-18T04:29:15.690Z,1621312155.690 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:16.087Z,1621312156.087 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=28.686495
2021-05-18T04:29:16.108Z,1621312156.108 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:16.503Z,1621312156.503 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=29.103348
2021-05-18T04:29:16.513Z,1621312156.513 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:16.905Z,1621312156.905 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=29.505234
2021-05-18T04:29:16.944Z,1621312156.944 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:17.309Z,1621312157.309 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=29.908607
2021-05-18T04:29:17.325Z,1621312157.325 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:17.706Z,1621312157.706 [DAT](INFO): ****** received valid address query ******
2021-05-18T04:29:17.706Z,1621312157.706 [DAT](INFO): ****** received valid ping request ******
2021-05-18T04:29:17.706Z,1621312157.706 [DAT](INFO): Querying Benthos address 50 with 5 pings in terminal homing one-way mode.
2021-05-18T04:29:17.709Z,1621312157.709 [DAT](INFO): ****** ping requested ******
2021-05-18T04:29:17.721Z,1621312157.721 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:18.102Z,1621312158.102 [DAT](INFO): DAT read: user:10>

2021-05-18T04:29:18.103Z,1621312158.103 [DAT](INFO): DAT read: Tx time:04:28:52.4787

2021-05-18T04:29:18.103Z,1621312158.103 [DAT](INFO): Ping request sent.
2021-05-18T04:29:18.104Z,1621312158.104 [DAT](INFO): transmitted an acoustic signal
2021-05-18T04:29:18.104Z,1621312158.104 [DAT](INFO): publishing transmit ping time
2021-05-18T04:29:18.105Z,1621312158.105 [DAT](INFO): checking for new query: numPingsReceived=0 elapsed TxPingTime=0.000923
2021-05-18T04:29:18.153Z,1621312158.153 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:18.153Z,1621312158.153 [lab_range_test:A.](INFO): update period (5.000000 s) has elapsed, querying...
2021-05-18T04:29:18.153Z,1621312158.153 [lab_range_test:A.](INFO): *** querying DAT ***
2021-05-18T04:29:18.506Z,1621312158.506 [DAT](INFO): checking for new query: numPingsReceived=0 elapsed TxPingTime=0.402838
2021-05-18T04:29:18.534Z,1621312158.534 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:18.915Z,1621312158.915 [DAT](INFO): checking for new query: numPingsReceived=0 elapsed TxPingTime=0.810933
2021-05-18T04:29:18.941Z,1621312158.941 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:19.338Z,1621312159.338 [DAT](INFO): checking for new query: numPingsReceived=0 elapsed TxPingTime=1.234190
2021-05-18T04:29:19.345Z,1621312159.345 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:19.734Z,1621312159.734 [DAT](INFO): checking for new query: numPingsReceived=0 elapsed TxPingTime=1.630499
2021-05-18T04:29:19.761Z,1621312159.761 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:20.137Z,1621312160.137 [DAT](INFO): checking for new query: numPingsReceived=0 elapsed TxPingTime=2.033677
2021-05-18T04:29:20.150Z,1621312160.150 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:20.540Z,1621312160.540 [DAT](INFO): DAT read: Rx Time:04:28:54.6083 

2021-05-18T04:29:20.540Z,1621312160.540 [DAT](INFO): received an acoustic signal
2021-05-18T04:29:20.542Z,1621312160.542 [DAT](INFO): DAT read: Bearing  71.3,  -6.8 (Local)

2021-05-18T04:29:20.542Z,1621312160.542 [DAT](INFO): Local bearing/azimuth received:
 Bearing  71.3,  -6.8 (Local)

2021-05-18T04:29:20.544Z,1621312160.544 [DAT](INFO): DAT read: Range 7 to 50 :     0.3 m (trip time 0.2 ms) speed 0.0

2021-05-18T04:29:20.545Z,1621312160.545 [DAT](ERROR): Read range message, but no direction.
2021-05-18T04:29:20.545Z,1621312160.545 [DAT](INFO): not publishing receive ping time as it could be a packet for anyone
2021-05-18T04:29:20.546Z,1621312160.546 [DAT](INFO): checking for new query: numPingsReceived=0 elapsed TxPingTime=2.442654
2021-05-18T04:29:20.555Z,1621312160.555 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:20.556Z,1621312160.556 [lab_range_test:A.](INFO): direction in vehicle frame: [ 0.201854 forward, 0.974715 starboard, -0.095846 keelward ]
2021-05-18T04:29:20.556Z,1621312160.556 [lab_range_test:A.](DEBUG): processing response from DAT
2021-05-18T04:29:20.558Z,1621312160.558 [lab_range_test:A.](INFO): rotationFromVehicleToNavigationFrame_ = [ 0.999301,-0.037294,-0.002469;0.037344,0.998995,0.024793;0.001542,-0.024868,0.999690 ]
2021-05-18T04:29:20.559Z,1621312160.559 [lab_range_test:A.](INFO): rangeToContact_ = 0.300000 m
2021-05-18T04:29:20.560Z,1621312160.560 [lab_range_test:A.](INFO): direction in world frame: [ 0.237964 north, 0.968591 east, -0.072148 down ]
2021-05-18T04:29:20.560Z,1621312160.560 [lab_range_test:A.](INFO): relPosInFSK: [ 0.060556 forward, 0.292414 starboard, -0.028754 keelward ]
2021-05-18T04:29:20.561Z,1621312160.561 [lab_range_test:A.](INFO): relPosInNED: [ 0.071389 north, 0.290577 east, -0.021644 down ]
2021-05-18T04:29:20.561Z,1621312160.561 [lab_range_test:A.](DEBUG): Combining 5 samples.
2021-05-18T04:29:20.562Z,1621312160.562 [lab_range_test:A.](DEBUG): Could not read vehicle position; cannot calculate contact position.
2021-05-18T04:29:20.955Z,1621312160.955 [DAT](INFO): DAT read: 04:28:54.6083 LVL= 32752, 32753, 32754, 32755, AGC= 67, IDX= 464, 0.15, 0.732, 0.464, 0.694, 0.671, PHS= 0.056,-0.164, 0.008, RAW= 138.0,   9.9, CAL= 138.7,   6.8, ROT=  71.3,  -6.8

2021-05-18T04:29:20.956Z,1621312160.956 [DAT](INFO): got valid direction response:
 04:28:54.6083 LVL= 32752, 32753, 32754, 32755, AGC= 67, IDX= 464, 0.15, 0.732, 0.464, 0.694, 0.671, PHS= 0.056,-0.164, 0.008, RAW= 138.0,   9.9, CAL= 138.7,   6.8, ROT=  71.3,  -6.8

2021-05-18T04:29:20.957Z,1621312160.957 [DAT](INFO): DAT read: Rx Time:04:28:55.1083 

2021-05-18T04:29:20.958Z,1621312160.958 [DAT](INFO): received an acoustic signal
2021-05-18T04:29:20.959Z,1621312160.959 [DAT](INFO): DAT read: Bearing  71.4,  -7.5 (Local)

2021-05-18T04:29:20.960Z,1621312160.960 [DAT](INFO): Local bearing/azimuth received:
 Bearing  71.4,  -7.5 (Local)

2021-05-18T04:29:20.961Z,1621312160.961 [DAT](INFO): DAT read: Range 7 to 50 :     0.3 m (trip time 0.2 ms) speed 0.0

2021-05-18T04:29:20.962Z,1621312160.962 [DAT](INFO): Read range and direction messages.
2021-05-18T04:29:20.963Z,1621312160.963 [DAT](INFO): direction in vehicle frame: [ 0.318358 forward, 0.940547 starboard, -0.118404 keelward ]
2021-05-18T04:29:20.964Z,1621312160.964 [DAT](INFO): not publishing receive ping time as it could be a packet for anyone
2021-05-18T04:29:20.964Z,1621312160.964 [DAT](INFO): publishing direction and range info
2021-05-18T04:29:20.968Z,1621312160.968 [DAT](INFO): checking for new query: numPingsReceived=1 elapsed TxPingTime=2.863872
2021-05-18T04:29:20.976Z,1621312160.976 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:20.978Z,1621312160.978 [lab_range_test:A.](INFO): direction in vehicle frame: [ 0.318358 forward, 0.940547 starboard, -0.118404 keelward ]
2021-05-18T04:29:20.978Z,1621312160.978 [lab_range_test:A.](DEBUG): processing response from DAT
2021-05-18T04:29:20.980Z,1621312160.980 [lab_range_test:A.](INFO): rotationFromVehicleToNavigationFrame_ = [ 0.999327,-0.036597,-0.002451;0.036647,0.999018,0.024898;0.001537,-0.024971,0.999687 ]
2021-05-18T04:29:20.981Z,1621312160.981 [lab_range_test:A.](INFO): rangeToContact_ = 0.300000 m
2021-05-18T04:29:20.982Z,1621312160.982 [lab_range_test:A.](INFO): direction in world frame: [ 0.352430 north, 0.930929 east, -0.095730 down ]
2021-05-18T04:29:20.983Z,1621312160.983 [lab_range_test:A.](INFO): relPosInFSK: [ 0.095507 forward, 0.282164 starboard, -0.035521 keelward ]
2021-05-18T04:29:20.984Z,1621312160.984 [lab_range_test:A.](INFO): relPosInNED: [ 0.105729 north, 0.279279 east, -0.028719 down ]
2021-05-18T04:29:20.984Z,1621312160.984 [lab_range_test:A.](DEBUG): Combining 5 samples.
2021-05-18T04:29:20.984Z,1621312160.984 [lab_range_test:A.](DEBUG): Could not read vehicle position; cannot calculate contact position.
2021-05-18T04:29:21.372Z,1621312161.372 [DAT](INFO): DAT read: 04:28:55.1083 LVL= 32752, 32753, 32754, 32755, AGC= 67, IDX= 496, 0.32, 0.509, 0.233, 0.469, 0.448, PHS= 0.056,-0.172, 0.006, RAW= 137.8,  10.6, CAL= 138.6,   7.5, ROT=  71.4,  -7.5

2021-05-18T04:29:21.373Z,1621312161.373 [DAT](INFO): got valid direction response:
 04:28:55.1083 LVL= 32752, 32753, 32754, 32755, AGC= 67, IDX= 496, 0.32, 0.509, 0.233, 0.469, 0.448, PHS= 0.056,-0.172, 0.006, RAW= 137.8,  10.6, CAL= 138.6,   7.5, ROT=  71.4,  -7.5

2021-05-18T04:29:21.374Z,1621312161.374 [DAT](INFO): DAT read: Rx Time:04:28:55.6083 

2021-05-18T04:29:21.374Z,1621312161.374 [DAT](INFO): received an acoustic signal
2021-05-18T04:29:21.376Z,1621312161.376 [DAT](INFO): DAT read: Bearing  68.2,  -9.3 (Local)

2021-05-18T04:29:21.377Z,1621312161.377 [DAT](INFO): Local bearing/azimuth received:
 Bearing  68.2,  -9.3 (Local)

2021-05-18T04:29:21.378Z,1621312161.378 [DAT](INFO): DAT read: Range 7 to 50 :     0.2 m (trip time 0.1 ms) speed 0.0

2021-05-18T04:29:21.379Z,1621312161.379 [DAT](INFO): Read range and direction messages.
2021-05-18T04:29:21.381Z,1621312161.381 [DAT](INFO): direction in vehicle frame: [ 0.316231 forward, 0.939660 starboard, -0.130526 keelward ]
2021-05-18T04:29:21.381Z,1621312161.381 [DAT](INFO): not publishing receive ping time as it could be a packet for anyone
2021-05-18T04:29:21.381Z,1621312161.381 [DAT](INFO): publishing direction and range info
2021-05-18T04:29:21.385Z,1621312161.385 [DAT](INFO): checking for new query: numPingsReceived=2 elapsed TxPingTime=3.281229
2021-05-18T04:29:21.394Z,1621312161.394 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:21.395Z,1621312161.395 [lab_range_test:A.](INFO): direction in vehicle frame: [ 0.316231 forward, 0.939660 starboard, -0.130526 keelward ]
2021-05-18T04:29:21.395Z,1621312161.395 [lab_range_test:A.](DEBUG): processing response from DAT
2021-05-18T04:29:21.398Z,1621312161.398 [lab_range_test:A.](INFO): rotationFromVehicleToNavigationFrame_ = [ 0.999344,-0.036145,-0.002419;0.036194,0.999033,0.024969;0.001514,-0.025040,0.999685 ]
2021-05-18T04:29:21.399Z,1621312161.399 [lab_range_test:A.](INFO): rangeToContact_ = 0.200000 m
2021-05-18T04:29:21.400Z,1621312161.400 [lab_range_test:A.](INFO): direction in world frame: [ 0.349836 north, 0.930589 east, -0.107787 down ]
2021-05-18T04:29:21.401Z,1621312161.401 [lab_range_test:A.](INFO): relPosInFSK: [ 0.063246 forward, 0.187932 starboard, -0.026105 keelward ]
2021-05-18T04:29:21.402Z,1621312161.402 [lab_range_test:A.](INFO): relPosInNED: [ 0.069967 north, 0.186118 east, -0.021557 down ]
2021-05-18T04:29:21.402Z,1621312161.402 [lab_range_test:A.](DEBUG): Combining 5 samples.
2021-05-18T04:29:21.402Z,1621312161.402 [lab_range_test:A.](DEBUG): Could not read vehicle position; cannot calculate contact position.
2021-05-18T04:29:21.770Z,1621312161.770 [DAT](INFO): DAT read: 04:28:55.6083 LVL= 32752, 32753, 32754, 32755, AGC= 67, IDX= 496,-0.43,-2.340,-2.658,-2.373,-2.396, PHS= 0.052,-0.218, 0.008, RAW= 141.2,  12.5, CAL= 141.8,   9.3, ROT=  68.2,  -9.3

2021-05-18T04:29:21.771Z,1621312161.771 [DAT](INFO): got valid direction response:
 04:28:55.6083 LVL= 32752, 32753, 32754, 32755, AGC= 67, IDX= 496,-0.43,-2.340,-2.658,-2.373,-2.396, PHS= 0.052,-0.218, 0.008, RAW= 141.2,  12.5, CAL= 141.8,   9.3, ROT=  68.2,  -9.3

2021-05-18T04:29:21.772Z,1621312161.772 [DAT](INFO): Read direction message, but no range.
2021-05-18T04:29:21.773Z,1621312161.773 [DAT](INFO): direction in vehicle frame: [ 0.366486 forward, 0.916282 starboard, -0.161604 keelward ]
2021-05-18T04:29:21.777Z,1621312161.777 [DAT](INFO): checking for new query: numPingsReceived=2 elapsed TxPingTime=3.673317
2021-05-18T04:29:21.811Z,1621312161.811 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:22.174Z,1621312162.174 [DAT](INFO): DAT read: Rx Time:04:28:56.1083 

2021-05-18T04:29:22.174Z,1621312162.174 [DAT](INFO): received an acoustic signal
2021-05-18T04:29:22.176Z,1621312162.176 [DAT](INFO): DAT read: Bearing  68.1,  -9.7 (Local)

2021-05-18T04:29:22.176Z,1621312162.176 [DAT](INFO): Local bearing/azimuth received:
 Bearing  68.1,  -9.7 (Local)

2021-05-18T04:29:22.178Z,1621312162.178 [DAT](INFO): DAT read: Range 7 to 50 :     0.3 m (trip time 0.2 ms) speed 0.0

2021-05-18T04:29:22.183Z,1621312162.183 [DAT](INFO): DAT read: 04:28:56.1083 LVL= 32752, 32753, 32754, 32755, AGC= 70, IDX=   1,-0.23,-1.304,-1.632,-1.338,-1.360, PHS= 0.052,-0.228, 0.007, RAW= 141.3,  12.9, CAL= 141.9,   9.7, ROT=  68.1,  -9.7

2021-05-18T04:29:22.184Z,1621312162.184 [DAT](INFO): got valid direction response:
 04:28:56.1083 LVL= 32752, 32753, 32754, 32755, AGC= 70, IDX=   1,-0.23,-1.304,-1.632,-1.338,-1.360, PHS= 0.052,-0.228, 0.007, RAW= 141.3,  12.9, CAL= 141.9,   9.7, ROT=  68.1,  -9.7

2021-05-18T04:29:22.184Z,1621312162.184 [DAT](INFO): Read range and direction messages.
2021-05-18T04:29:22.185Z,1621312162.185 [DAT](INFO): direction in vehicle frame: [ 0.367655 forward, 0.914571 starboard, -0.168489 keelward ]
2021-05-18T04:29:22.185Z,1621312162.185 [DAT](INFO): not publishing receive ping time as it could be a packet for anyone
2021-05-18T04:29:22.186Z,1621312162.186 [DAT](INFO): publishing direction and range info
2021-05-18T04:29:22.189Z,1621312162.189 [DAT](INFO): checking for new query: numPingsReceived=3 elapsed TxPingTime=4.085090
2021-05-18T04:29:22.197Z,1621312162.197 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:22.198Z,1621312162.198 [lab_range_test:A.](INFO): direction in vehicle frame: [ 0.367655 forward, 0.914571 starboard, -0.168489 keelward ]
2021-05-18T04:29:22.198Z,1621312162.198 [lab_range_test:A.](DEBUG): processing response from DAT
2021-05-18T04:29:22.200Z,1621312162.200 [lab_range_test:A.](INFO): rotationFromVehicleToNavigationFrame_ = [ 0.999338,-0.036288,-0.002479;0.036339,0.999028,0.024951;0.001572,-0.025024,0.999686 ]
2021-05-18T04:29:22.201Z,1621312162.201 [lab_range_test:A.](INFO): rangeToContact_ = 0.300000 m
2021-05-18T04:29:22.201Z,1621312162.201 [lab_range_test:A.](INFO): direction in world frame: [ 0.400382 north, 0.904557 east, -0.146529 down ]
2021-05-18T04:29:22.202Z,1621312162.202 [lab_range_test:A.](INFO): relPosInFSK: [ 0.110297 forward, 0.274371 starboard, -0.050547 keelward ]
2021-05-18T04:29:22.215Z,1621312162.215 [lab_range_test:A.](INFO): relPosInNED: [ 0.120115 north, 0.271367 east, -0.043959 down ]
2021-05-18T04:29:22.216Z,1621312162.216 [lab_range_test:A.](DEBUG): Combining 5 samples.
2021-05-18T04:29:22.216Z,1621312162.216 [lab_range_test:A.](DEBUG): Could not read vehicle position; cannot calculate contact position.
2021-05-18T04:29:22.557Z,1621312162.557 [DAT](INFO): DAT read: Rx Time:04:28:56.6083 

2021-05-18T04:29:22.557Z,1621312162.557 [DAT](INFO): received an acoustic signal
2021-05-18T04:29:22.559Z,1621312162.559 [DAT](INFO): DAT read: Bearing  69.3,  -8.6 (Local)

2021-05-18T04:29:22.559Z,1621312162.559 [DAT](INFO): Local bearing/azimuth received:
 Bearing  69.3,  -8.6 (Local)

2021-05-18T04:29:22.561Z,1621312162.561 [DAT](INFO): DAT read: Range 7 to 50 :     0.2 m (trip time 0.1 ms) speed 0.0

2021-05-18T04:29:22.566Z,1621312162.566 [DAT](INFO): DAT read: 04:28:56.6083 LVL= 32752, 32753, 32754, 32755, AGC= 67, IDX= 496,-0.07,-2.019,-2.334,-2.056,-2.079, PHS= 0.057,-0.210, 0.008, RAW= 140.2,  11.8, CAL= 140.7,   8.6, ROT=  69.3,  -8.6

2021-05-18T04:29:22.567Z,1621312162.567 [DAT](INFO): got valid direction response:
 04:28:56.6083 LVL= 32752, 32753, 32754, 32755, AGC= 67, IDX= 496,-0.07,-2.019,-2.334,-2.056,-2.079, PHS= 0.057,-0.210, 0.008, RAW= 140.2,  11.8, CAL= 140.7,   8.6, ROT=  69.3,  -8.6

2021-05-18T04:29:22.568Z,1621312162.568 [DAT](INFO): Read range and direction messages.
2021-05-18T04:29:22.569Z,1621312162.569 [DAT](INFO): direction in vehicle frame: [ 0.349500 forward, 0.924926 starboard, -0.149535 keelward ]
2021-05-18T04:29:22.569Z,1621312162.569 [DAT](INFO): not publishing receive ping time as it could be a packet for anyone
2021-05-18T04:29:22.569Z,1621312162.569 [DAT](INFO): publishing direction and range info
2021-05-18T04:29:22.572Z,1621312162.572 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=4.468696
2021-05-18T04:29:22.604Z,1621312162.604 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:22.605Z,1621312162.605 [lab_range_test:A.](INFO): direction in vehicle frame: [ 0.349500 forward, 0.924926 starboard, -0.149535 keelward ]
2021-05-18T04:29:22.605Z,1621312162.605 [lab_range_test:A.](DEBUG): processing response from DAT
2021-05-18T04:29:22.612Z,1621312162.612 [lab_range_test:A.](INFO): rotationFromVehicleToNavigationFrame_ = [ 0.999360,-0.035685,-0.002567;0.035738,0.999048,0.024997;0.001673,-0.025073,0.999684 ]
2021-05-18T04:29:22.612Z,1621312162.612 [lab_range_test:A.](INFO): rangeToContact_ = 0.200000 m
2021-05-18T04:29:22.613Z,1621312162.613 [lab_range_test:A.](INFO): direction in world frame: [ 0.382082 north, 0.915324 east, -0.127265 down ]
2021-05-18T04:29:22.613Z,1621312162.613 [lab_range_test:A.](INFO): relPosInFSK: [ 0.069900 forward, 0.184985 starboard, -0.029907 keelward ]
2021-05-18T04:29:22.614Z,1621312162.614 [lab_range_test:A.](INFO): relPosInNED: [ 0.076416 north, 0.183065 east, -0.025453 down ]
2021-05-18T04:29:22.614Z,1621312162.614 [lab_range_test:A.](DEBUG): Combining 5 samples.
2021-05-18T04:29:22.615Z,1621312162.615 [lab_range_test:A.](DEBUG): Could not read vehicle position; cannot calculate contact position.
2021-05-18T04:29:22.964Z,1621312162.964 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=4.860679
2021-05-18T04:29:22.982Z,1621312162.982 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:23.369Z,1621312163.369 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=5.265303
2021-05-18T04:29:23.393Z,1621312163.393 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:23.773Z,1621312163.773 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=5.669128
2021-05-18T04:29:23.785Z,1621312163.785 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:24.181Z,1621312164.181 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=6.077663
2021-05-18T04:29:24.189Z,1621312164.189 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:24.566Z,1621312164.566 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=6.462487
2021-05-18T04:29:24.591Z,1621312164.591 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:24.974Z,1621312164.974 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=6.870849
2021-05-18T04:29:24.982Z,1621312164.982 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:25.378Z,1621312165.378 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=7.274733
2021-05-18T04:29:25.385Z,1621312165.385 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:25.779Z,1621312165.779 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=7.675096
2021-05-18T04:29:25.793Z,1621312165.793 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:26.187Z,1621312166.187 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=8.082925
2021-05-18T04:29:26.209Z,1621312166.209 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:26.605Z,1621312166.605 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=8.501214
2021-05-18T04:29:26.612Z,1621312166.612 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:27.005Z,1621312167.005 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=8.901353
2021-05-18T04:29:27.030Z,1621312167.030 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:27.405Z,1621312167.405 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=9.301192
2021-05-18T04:29:27.417Z,1621312167.417 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:27.807Z,1621312167.807 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=9.703055
2021-05-18T04:29:27.814Z,1621312167.814 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:27.815Z,1621312167.815 [lab_range_test:A.](INFO): update period (5.000000 s) has elapsed, querying...
2021-05-18T04:29:27.815Z,1621312167.815 [lab_range_test:A.](INFO): *** querying DAT ***
2021-05-18T04:29:28.203Z,1621312168.203 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=10.098839
2021-05-18T04:29:28.233Z,1621312168.233 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:28.607Z,1621312168.607 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=10.503825
2021-05-18T04:29:28.615Z,1621312168.615 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:29.012Z,1621312169.012 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=10.908725
2021-05-18T04:29:29.020Z,1621312169.020 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:29.429Z,1621312169.429 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=11.325036
2021-05-18T04:29:29.441Z,1621312169.441 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:29.836Z,1621312169.836 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=11.732801
2021-05-18T04:29:29.850Z,1621312169.850 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:30.233Z,1621312170.233 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=12.129259
2021-05-18T04:29:30.269Z,1621312170.269 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:30.626Z,1621312170.626 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=12.522548
2021-05-18T04:29:30.637Z,1621312170.637 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:31.035Z,1621312171.035 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=12.931063
2021-05-18T04:29:31.057Z,1621312171.057 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:31.096Z,1621312171.096 [CommandLine](IMPORTANT): got command stop
2021-05-18T04:29:31.096Z,1621312171.096 [CommandLine](IMPORTANT): Scheduling is paused
2021-05-18T04:29:31.096Z,1621312171.096 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2021-05-18T04:29:31.435Z,1621312171.435 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=13.330845
2021-05-18T04:29:31.466Z,1621312171.466 [lab_range_test:A.](DEBUG): Tracking...
2021-05-18T04:29:31.466Z,1621312171.466 [MissionManager](INFO): MissionManager is completed.
2021-05-18T04:29:31.466Z,1621312171.466 [MissionManager](INFO): Uninitializing Mission lab_range_test
2021-05-18T04:29:31.466Z,1621312171.466 [lab_range_test] Stopped
2021-05-18T04:29:31.466Z,1621312171.466 [lab_range_test](DEBUG): Aggregate::uninitialize lab_range_test
2021-05-18T04:29:31.466Z,1621312171.466 [lab_range_test:A.] Stopped
2021-05-18T04:29:31.467Z,1621312171.467 [lab_range_test:A.](DEBUG): Uninitializing Tracking.
2021-05-18T04:29:31.471Z,1621312171.471 [lab_range_test:B.Wait] Stopped
2021-05-18T04:29:31.471Z,1621312171.471 [lab_range_test:B.Wait](DEBUG): Uninitialize Wait Component.
2021-05-18T04:29:31.840Z,1621312171.840 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=13.736060
2021-05-18T04:29:31.857Z,1621312171.857 [MissionManager](IMPORTANT): Started mission Default
2021-05-18T04:29:31.857Z,1621312171.857 [Default] Running Loop=1
2021-05-18T04:29:31.857Z,1621312171.857 [Default](DEBUG): Aggregate::initialize Default
2021-05-18T04:29:31.857Z,1621312171.857 [Default:B.GoToSurface] Running Loop=1
2021-05-18T04:29:31.857Z,1621312171.857 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2021-05-18T04:29:31.858Z,1621312171.858 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2021-05-18T04:29:31.858Z,1621312171.858 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2021-05-18T04:29:31.858Z,1621312171.858 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2021-05-18T04:29:31.859Z,1621312171.859 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2021-05-18T04:29:31.879Z,1621312171.879 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2021-05-18T04:29:31.880Z,1621312171.880 [Default:A.Wait] Running Loop=1
2021-05-18T04:29:31.880Z,1621312171.880 [Default:A.Wait](DEBUG): Initialize Wait Component.
2021-05-18T04:29:32.242Z,1621312172.242 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=14.138473
2021-05-18T04:29:32.657Z,1621312172.657 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=14.553326
2021-05-18T04:29:33.067Z,1621312173.067 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=14.963686
2021-05-18T04:29:33.465Z,1621312173.465 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=15.361397
2021-05-18T04:29:33.867Z,1621312173.867 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=15.763179
2021-05-18T04:29:34.266Z,1621312174.266 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=16.162483
2021-05-18T04:29:34.667Z,1621312174.667 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=16.563202
2021-05-18T04:29:35.071Z,1621312175.071 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=16.967381
2021-05-18T04:29:35.485Z,1621312175.485 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=17.380995
2021-05-18T04:29:35.897Z,1621312175.897 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=17.793571
2021-05-18T04:29:36.293Z,1621312176.293 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=18.189276
2021-05-18T04:29:36.686Z,1621312176.686 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=18.582485
2021-05-18T04:29:37.091Z,1621312177.091 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=18.986921
2021-05-18T04:29:37.501Z,1621312177.501 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=19.397081
2021-05-18T04:29:37.899Z,1621312177.899 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=19.795326
2021-05-18T04:29:38.302Z,1621312178.302 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=20.198181
2021-05-18T04:29:38.717Z,1621312178.717 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=20.613167
2021-05-18T04:29:39.137Z,1621312179.137 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=21.033459
2021-05-18T04:29:39.525Z,1621312179.525 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=21.421267
2021-05-18T04:29:39.919Z,1621312179.919 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=21.815348
2021-05-18T04:29:40.322Z,1621312180.322 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=22.218168
2021-05-18T04:29:40.740Z,1621312180.740 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=22.636793
2021-05-18T04:29:41.131Z,1621312181.131 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=23.027205
2021-05-18T04:29:41.549Z,1621312181.549 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=23.445030
2021-05-18T04:29:41.953Z,1621312181.953 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=23.849550
2021-05-18T04:29:42.353Z,1621312182.353 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=24.249334
2021-05-18T04:29:42.750Z,1621312182.750 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=24.646357
2021-05-18T04:29:43.151Z,1621312183.151 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=25.046932
2021-05-18T04:29:43.555Z,1621312183.555 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=25.451567
2021-05-18T04:29:43.963Z,1621312183.963 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=25.858854
2021-05-18T04:29:44.377Z,1621312184.377 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=26.273314
2021-05-18T04:29:44.785Z,1621312184.785 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=26.681202
2021-05-18T04:29:45.185Z,1621312185.185 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=27.081404
2021-05-18T04:29:45.198Z,1621312185.198 [Default:A.Wait](INFO): Done Waiting.
2021-05-18T04:29:45.198Z,1621312185.198 [Default:A.Wait] Stopped
2021-05-18T04:29:45.198Z,1621312185.198 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2021-05-18T04:29:45.578Z,1621312185.578 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=27.474562
2021-05-18T04:29:45.603Z,1621312185.603 [Default:CheckIn] Running Loop=1
2021-05-18T04:29:45.603Z,1621312185.603 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2021-05-18T04:29:45.603Z,1621312185.603 [Default:CheckIn:Read_GPS] Running Loop=1
2021-05-18T04:29:45.979Z,1621312185.979 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=27.875364
2021-05-18T04:29:46.386Z,1621312186.386 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=28.282347
2021-05-18T04:29:46.787Z,1621312186.787 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=28.683138
2021-05-18T04:29:47.197Z,1621312187.197 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=29.093307
2021-05-18T04:29:47.609Z,1621312187.609 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=29.505131
2021-05-18T04:29:48.013Z,1621312188.013 [DAT](INFO): checking for new query: numPingsReceived=4 elapsed TxPingTime=29.909580