2022-02-17T00:00:50.914Z,1645056050.914 [Supervisor](DEBUG): Initializing supervisor.
2022-02-17T00:00:50.919Z,1645056050.919 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2022-02-17T00:00:50.920Z,1645056050.920 [SyncHandler](INFO): Protected caller Thread ID is 6845
2022-02-17T00:00:50.920Z,1645056050.920 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2022-02-17T00:00:50.921Z,1645056050.921 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2022-02-17T00:00:50.922Z,1645056050.922 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 6846
2022-02-17T00:00:50.926Z,1645056050.926 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2022-02-17T00:00:50.944Z,1645056050.944 [ComponentRegistry](DEBUG): Component "CommandExec" handled in its own thread.
2022-02-17T00:00:50.945Z,1645056050.945 [CommandExec ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2022-02-17T00:00:50.946Z,1645056050.946 [CommandExec ThreadHandler](INFO): Protected caller Thread ID is 6847
2022-02-17T00:00:50.950Z,1645056050.950 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2022-02-17T00:00:50.951Z,1645056050.951 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2022-02-17T00:00:50.951Z,1645056050.951 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 6848
2022-02-17T00:00:50.953Z,1645056050.953 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2022-02-17T00:00:50.954Z,1645056050.954 [logger ThreadHandler](DEBUG): Created PCaller Thread at 405114E0
2022-02-17T00:00:50.955Z,1645056050.955 [logger ThreadHandler](INFO): Protected caller Thread ID is 6849
2022-02-17T00:00:50.958Z,1645056050.958 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2022-02-17T00:00:50.959Z,1645056050.959 [Supervisor](INFO): Looking for Config files in directory: Config/
2022-02-17T00:00:50.960Z,1645056050.960 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2022-02-17T00:00:51.382Z,1645056051.382 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2022-02-17T00:00:51.383Z,1645056051.383 [Supervisor](INFO): Opening Config file at: Config/Dock.cfg
2022-02-17T00:00:51.598Z,1645056051.598 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Dock
2022-02-17T00:00:51.599Z,1645056051.599 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2022-02-17T00:00:51.788Z,1645056051.788 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2022-02-17T00:00:51.789Z,1645056051.789 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2022-02-17T00:00:51.894Z,1645056051.894 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2022-02-17T00:00:51.895Z,1645056051.895 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2022-02-17T00:00:52.258Z,1645056052.258 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2022-02-17T00:00:52.259Z,1645056052.259 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2022-02-17T00:00:52.589Z,1645056052.589 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2022-02-17T00:00:52.589Z,1645056052.589 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2022-02-17T00:00:52.684Z,1645056052.684 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2022-02-17T00:00:52.684Z,1645056052.684 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2022-02-17T00:00:52.832Z,1645056052.832 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2022-02-17T00:00:52.832Z,1645056052.832 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2022-02-17T00:00:53.362Z,1645056053.362 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2022-02-17T00:00:53.363Z,1645056053.363 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2022-02-17T00:00:53.716Z,1645056053.716 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2022-02-17T00:00:53.717Z,1645056053.717 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2022-02-17T00:00:53.796Z,1645056053.796 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2022-02-17T00:00:54.007Z,1645056054.007 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2022-02-17T00:00:54.008Z,1645056054.008 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2022-02-17T00:00:54.133Z,1645056054.133 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2022-02-17T00:00:54.133Z,1645056054.133 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2022-02-17T00:00:54.840Z,1645056054.840 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2022-02-17T00:00:54.841Z,1645056054.841 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2022-02-17T00:00:54.918Z,1645056054.918 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2022-02-17T00:00:55.518Z,1645056055.518 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2022-02-17T00:00:55.520Z,1645056055.520 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-galene/
2022-02-17T00:00:55.521Z,1645056055.521 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/vehicle.cfg
2022-02-17T00:00:55.837Z,1645056055.837 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/logger.cfg
2022-02-17T00:00:55.934Z,1645056055.934 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/Servo.cfg
2022-02-17T00:00:56.045Z,1645056056.045 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/Control.cfg
2022-02-17T00:00:56.143Z,1645056056.143 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/secure.cfg
2022-02-17T00:00:56.225Z,1645056056.225 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/Simulator.cfg
2022-02-17T00:00:56.310Z,1645056056.310 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/Science.cfg
2022-02-17T00:00:56.424Z,1645056056.424 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/BIT.cfg
2022-02-17T00:00:56.522Z,1645056056.522 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/Sensor.cfg
2022-02-17T00:00:56.675Z,1645056056.675 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/Battery.cfg
2022-02-17T00:00:56.934Z,1645056056.934 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2022-02-17T00:00:56.935Z,1645056056.935 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/Navigation.cfg
2022-02-17T00:00:57.030Z,1645056057.030 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-galene/root/
2022-02-17T00:00:57.030Z,1645056057.030 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2022-02-17T00:00:57.045Z,1645056057.045 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2022-02-17T00:00:57.365Z,1645056057.365 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2022-02-17T00:00:57.366Z,1645056057.366 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2022-02-17T00:00:57.480Z,1645056057.480 [DeadReckonUsingMultipleVelocitySources] Loaded
2022-02-17T00:00:57.480Z,1645056057.480 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2022-02-17T00:00:57.517Z,1645056057.517 [DeadReckonUsingSpeedCalculator] Loaded
2022-02-17T00:00:57.517Z,1645056057.517 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingSpeedCalculator" handled in the control thread.
2022-02-17T00:00:57.530Z,1645056057.530 [NavChart] Loaded
2022-02-17T00:00:57.530Z,1645056057.530 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2022-02-17T00:00:57.536Z,1645056057.536 [UniversalFixResidualReporter] Loaded
2022-02-17T00:00:57.536Z,1645056057.536 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2022-02-17T00:00:57.536Z,1645056057.536 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2022-02-17T00:00:57.537Z,1645056057.537 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2022-02-17T00:00:57.547Z,1645056057.547 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2022-02-17T00:00:57.548Z,1645056057.548 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2022-02-17T00:00:57.742Z,1645056057.742 [CTD_Seabird] Loaded
2022-02-17T00:00:57.742Z,1645056057.742 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread.
2022-02-17T00:00:57.743Z,1645056057.743 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 406614E0
2022-02-17T00:00:57.744Z,1645056057.744 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 6931
2022-02-17T00:00:57.763Z,1645056057.763 [PAR_Licor] Loaded
2022-02-17T00:00:57.764Z,1645056057.764 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2022-02-17T00:00:57.794Z,1645056057.794 [WetLabsBB2FL] Loaded
2022-02-17T00:00:57.794Z,1645056057.794 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2022-02-17T00:00:57.795Z,1645056057.795 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 406914E0
2022-02-17T00:00:57.796Z,1645056057.796 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 6932
2022-02-17T00:00:57.796Z,1645056057.796 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2022-02-17T00:00:57.797Z,1645056057.797 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2022-02-17T00:00:57.849Z,1645056057.849 [VerticalControl](DEBUG): Construct VerticalControl.
2022-02-17T00:00:57.909Z,1645056057.909 [VerticalControl] Loaded
2022-02-17T00:00:57.909Z,1645056057.909 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2022-02-17T00:00:57.911Z,1645056057.911 [HorizontalControl](DEBUG): Construct HorizontalControl.
2022-02-17T00:00:57.950Z,1645056057.950 [HorizontalControl] Loaded
2022-02-17T00:00:57.950Z,1645056057.950 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2022-02-17T00:00:57.953Z,1645056057.953 [SpeedControl](DEBUG): Construct SpeedControl.
2022-02-17T00:00:57.956Z,1645056057.956 [SpeedControl] Loaded
2022-02-17T00:00:57.956Z,1645056057.956 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2022-02-17T00:00:57.958Z,1645056057.958 [LoopControl](DEBUG): Construct LoopControl.
2022-02-17T00:00:57.959Z,1645056057.959 [LoopControl] Loaded
2022-02-17T00:00:57.959Z,1645056057.959 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2022-02-17T00:00:57.960Z,1645056057.960 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2022-02-17T00:00:57.960Z,1645056057.960 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2022-02-17T00:00:58.002Z,1645056058.002 [DepthRateCalculator] Loaded
2022-02-17T00:00:58.003Z,1645056058.003 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2022-02-17T00:00:58.007Z,1645056058.007 [PitchRateCalculator] Loaded
2022-02-17T00:00:58.007Z,1645056058.007 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2022-02-17T00:00:58.017Z,1645056058.017 [SpeedCalculator] Loaded
2022-02-17T00:00:58.017Z,1645056058.017 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2022-02-17T00:00:58.030Z,1645056058.030 [TempGradientCalculator] Loaded
2022-02-17T00:00:58.030Z,1645056058.030 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2022-02-17T00:00:58.034Z,1645056058.034 [YawRateCalculator] Loaded
2022-02-17T00:00:58.034Z,1645056058.034 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2022-02-17T00:00:58.052Z,1645056058.052 [ElevatorOffsetCalculator] Loaded
2022-02-17T00:00:58.052Z,1645056058.052 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2022-02-17T00:00:58.053Z,1645056058.053 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2022-02-17T00:00:58.053Z,1645056058.053 [Module Loader](DEBUG): Loading Module at Modules/Dock.so
2022-02-17T00:00:58.150Z,1645056058.150 [Module Loader](DEBUG): Loaded Module: Dock (Contains behaviors and commands for docking)
2022-02-17T00:00:58.151Z,1645056058.151 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2022-02-17T00:00:58.209Z,1645056058.209 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2022-02-17T00:00:58.209Z,1645056058.209 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2022-02-17T00:00:58.335Z,1645056058.335 [BuoyancyServo] Loaded
2022-02-17T00:00:58.335Z,1645056058.335 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2022-02-17T00:00:58.354Z,1645056058.354 [ElevatorServo] Loaded
2022-02-17T00:00:58.355Z,1645056058.355 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2022-02-17T00:00:58.373Z,1645056058.373 [MassServo] Loaded
2022-02-17T00:00:58.374Z,1645056058.374 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2022-02-17T00:00:58.392Z,1645056058.392 [RudderServo] Loaded
2022-02-17T00:00:58.392Z,1645056058.392 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2022-02-17T00:00:58.407Z,1645056058.407 [ThrusterHE] Loaded
2022-02-17T00:00:58.408Z,1645056058.408 [ComponentRegistry](DEBUG): SyncComponent "ThrusterHE" handled in the control thread.
2022-02-17T00:00:58.408Z,1645056058.408 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2022-02-17T00:00:58.409Z,1645056058.409 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2022-02-17T00:00:58.511Z,1645056058.511 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2022-02-17T00:00:58.511Z,1645056058.511 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2022-02-17T00:00:58.913Z,1645056058.913 [AHRS_M2] Loaded
2022-02-17T00:00:58.913Z,1645056058.913 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2022-02-17T00:00:58.949Z,1645056058.949 [BackseatComponent] Loaded
2022-02-17T00:00:58.949Z,1645056058.949 [ComponentRegistry](DEBUG): Component "BackseatComponent" handled in its own thread.
2022-02-17T00:00:58.950Z,1645056058.950 [BackseatComponent ThreadHandler](DEBUG): Created PCaller Thread at 40A774E0
2022-02-17T00:00:58.950Z,1645056058.950 [BackseatComponent ThreadHandler](INFO): Protected caller Thread ID is 6933
2022-02-17T00:00:58.953Z,1645056058.953 [LcmUniversalReporter] Loaded
2022-02-17T00:00:58.953Z,1645056058.953 [ComponentRegistry](DEBUG): SyncComponent "LcmUniversalReporter" handled in the control thread.
2022-02-17T00:00:59.787Z,1645056059.787 [BPC1] Loaded
2022-02-17T00:00:59.788Z,1645056059.788 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2022-02-17T00:00:59.859Z,1645056059.859 [DataOverHttps] Loaded
2022-02-17T00:00:59.859Z,1645056059.859 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2022-02-17T00:00:59.860Z,1645056059.860 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 40AA74E0
2022-02-17T00:00:59.860Z,1645056059.860 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 6934
2022-02-17T00:00:59.880Z,1645056059.880 [Depth_Keller] Loaded
2022-02-17T00:00:59.880Z,1645056059.880 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2022-02-17T00:00:59.940Z,1645056059.940 [NAL9602] Loaded
2022-02-17T00:00:59.940Z,1645056059.940 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2022-02-17T00:00:59.969Z,1645056059.969 [Onboard] Loaded
2022-02-17T00:00:59.969Z,1645056059.969 [ComponentRegistry](DEBUG): Component "Onboard" handled in its own thread.
2022-02-17T00:00:59.970Z,1645056059.970 [Onboard ThreadHandler](DEBUG): Created PCaller Thread at 40AD74E0
2022-02-17T00:00:59.970Z,1645056059.970 [Onboard ThreadHandler](INFO): Protected caller Thread ID is 6935
2022-02-17T00:00:59.982Z,1645056059.982 [Power24vConverter] Loaded
2022-02-17T00:00:59.982Z,1645056059.982 [ComponentRegistry](DEBUG): SyncComponent "Power24vConverter" handled in the control thread.
2022-02-17T00:00:59.995Z,1645056059.995 [Radio_Surface] Loaded
2022-02-17T00:00:59.995Z,1645056059.995 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2022-02-17T00:00:59.996Z,1645056059.996 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 40B074E0
2022-02-17T00:00:59.996Z,1645056059.996 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 6936
2022-02-17T00:01:00.080Z,1645056060.080 [DAT] Loaded
2022-02-17T00:01:00.080Z,1645056060.080 [ComponentRegistry](DEBUG): Component "DAT" handled in its own thread.
2022-02-17T00:01:00.081Z,1645056060.081 [DAT ThreadHandler](DEBUG): Created PCaller Thread at 40B374E0
2022-02-17T00:01:00.081Z,1645056060.081 [DAT ThreadHandler](INFO): Protected caller Thread ID is 6937
2022-02-17T00:01:00.082Z,1645056060.082 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2022-02-17T00:01:00.082Z,1645056060.082 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2022-02-17T00:01:00.229Z,1645056060.229 [SBIT](DEBUG): Construct Startup Built In Test.
2022-02-17T00:01:00.237Z,1645056060.237 [SBIT] Loaded
2022-02-17T00:01:00.238Z,1645056060.238 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2022-02-17T00:01:00.240Z,1645056060.240 [IBIT](DEBUG): Construct Initiated Built In Test.
2022-02-17T00:01:00.253Z,1645056060.253 [IBIT] Loaded
2022-02-17T00:01:00.253Z,1645056060.253 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2022-02-17T00:01:00.259Z,1645056060.259 [CBIT](DEBUG): Construct Continuous Built In Test.
2022-02-17T00:01:00.361Z,1645056060.361 [CBIT] Loaded
2022-02-17T00:01:00.362Z,1645056060.362 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2022-02-17T00:01:00.362Z,1645056060.362 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2022-02-17T00:01:00.363Z,1645056060.363 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2022-02-17T00:01:00.391Z,1645056060.391 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2022-02-17T00:01:00.397Z,1645056060.397 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2022-02-17T00:01:00.399Z,1645056060.399 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2022-02-17T00:01:00.411Z,1645056060.411 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2022-02-17T00:01:00.412Z,1645056060.412 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40BC44E0
2022-02-17T00:01:00.412Z,1645056060.412 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 6938
2022-02-17T00:01:00.417Z,1645056060.417 [Supervisor](INFO): Main Thread ID is 6713
2022-02-17T00:01:00.417Z,1645056060.417 [Supervisor](DEBUG): Running supervisor.
2022-02-17T00:01:00.417Z,1645056060.417 [CommandExec ThreadHandler](INFO): Handler Thread ID is 6939
2022-02-17T00:01:00.418Z,1645056060.418 [CommandExec](INFO): Initializing the command executive.
2022-02-17T00:01:00.419Z,1645056060.419 [CommandLine ThreadHandler](INFO): Handler Thread ID is 6940
2022-02-17T00:01:00.421Z,1645056060.421 [controlThread ThreadHandler](INFO): Handler Thread ID is 6941
2022-02-17T00:01:00.422Z,1645056060.422 [controlThread](DEBUG): Initializing ControlThread
2022-02-17T00:01:00.423Z,1645056060.423 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2022-02-17T00:01:00.424Z,1645056060.424 [NavChart](DEBUG): Initialize NavChart Navigation.
2022-02-17T00:01:00.424Z,1645056060.424 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2022-02-17T00:01:00.428Z,1645056060.428 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2022-02-17T00:01:00.430Z,1645056060.430 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2022-02-17T00:01:00.430Z,1645056060.430 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2022-02-17T00:01:00.431Z,1645056060.431 [LoopControl](DEBUG): Initialize LoopControlComponent.
2022-02-17T00:01:00.431Z,1645056060.431 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2022-02-17T00:01:00.431Z,1645056060.431 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2022-02-17T00:01:00.432Z,1645056060.432 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2022-02-17T00:01:00.432Z,1645056060.432 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2022-02-17T00:01:00.433Z,1645056060.433 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2022-02-17T00:01:00.433Z,1645056060.433 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2022-02-17T00:01:00.437Z,1645056060.437 [SBIT](INFO): Initialize SBIT Component.
2022-02-17T00:01:00.437Z,1645056060.437 [SBIT](IMPORTANT): git: 2022-02-01-38-g2d821a05a
2022-02-17T00:01:00.437Z,1645056060.437 [SBIT](INFO): git hash: 2d821a05a5d7bd869793495f80484f76d730284c
2022-02-17T00:01:00.438Z,1645056060.438 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2022-02-17T00:01:00.439Z,1645056060.439 [SBIT](INFO): Kernel Reporting Different Version From Configuration.
Kernel Expected: #2 PREEMPT Thu Jan 11 20:13:48 PST 2018
Kernel Reported: #1 PREEMPT Wed Mar 17 08:23:48 PDT 2021
2022-02-17T00:01:00.440Z,1645056060.440 [SBIT](INFO): Beginning SBIT in 38.000000 seconds.
2022-02-17T00:01:00.441Z,1645056060.441 [IBIT](INFO): Initialize IBIT Component.
2022-02-17T00:01:00.441Z,1645056060.441 [CBIT](DEBUG): Initialize CBIT Component.
2022-02-17T00:01:00.442Z,1645056060.442 [logger ThreadHandler](INFO): Handler Thread ID is 6942
2022-02-17T00:01:00.456Z,1645056060.456 [CBIT](DEBUG): Initialized mux pins.
2022-02-17T00:01:00.456Z,1645056060.456 [CBIT](DEBUG): Initializing the watchdog timer.
2022-02-17T00:01:00.460Z,1645056060.460 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 6943
2022-02-17T00:01:00.461Z,1645056060.461 [CTD_Seabird](DEBUG): Initializing CTD_Seabird.
2022-02-17T00:01:00.465Z,1645056060.465 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 6945
2022-02-17T00:01:00.469Z,1645056060.469 [WetLabsBB2FL](INFO): Powering up
2022-02-17T00:01:00.470Z,1645056060.470 [BackseatComponent ThreadHandler](INFO): Handler Thread ID is 6947
2022-02-17T00:01:00.477Z,1645056060.477 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 6948
2022-02-17T00:01:00.477Z,1645056060.477 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2022-02-17T00:01:00.480Z,1645056060.480 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2022-02-17T00:01:00.480Z,1645056060.480 [CBIT](DEBUG): Initializing heartbeat.
2022-02-17T00:01:00.488Z,1645056060.488 [Onboard ThreadHandler](INFO): Handler Thread ID is 6949
2022-02-17T00:01:00.506Z,1645056060.506 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 6950
2022-02-17T00:01:00.528Z,1645056060.528 [DAT ThreadHandler](INFO): Handler Thread ID is 6951
2022-02-17T00:01:00.529Z,1645056060.529 [DAT](INFO): Powering up
2022-02-17T00:01:00.529Z,1645056060.529 [DAT](DEBUG): Initializing DAT.
2022-02-17T00:01:00.533Z,1645056060.533 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 6953
2022-02-17T00:01:00.536Z,1645056060.536 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2022-02-17T00:01:00.537Z,1645056060.537 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2022-02-17T00:01:00.537Z,1645056060.537 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2022-02-17T00:01:00.537Z,1645056060.537 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2022-02-17T00:01:00.537Z,1645056060.537 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2022-02-17T00:01:00.537Z,1645056060.537 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2022-02-17T00:01:00.538Z,1645056060.538 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2022-02-17T00:01:00.538Z,1645056060.538 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2022-02-17T00:01:00.538Z,1645056060.538 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2022-02-17T00:01:00.538Z,1645056060.538 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2022-02-17T00:01:00.538Z,1645056060.538 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2022-02-17T00:01:00.538Z,1645056060.538 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2022-02-17T00:01:00.539Z,1645056060.539 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2022-02-17T00:01:00.539Z,1645056060.539 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2022-02-17T00:01:00.539Z,1645056060.539 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2022-02-17T00:01:00.539Z,1645056060.539 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2022-02-17T00:01:00.552Z,1645056060.552 [CBIT](DEBUG): Deactivating GF circuits.
2022-02-17T00:01:00.552Z,1645056060.552 [CBIT](DEBUG): Deactivating emergency mode.
2022-02-17T00:01:00.588Z,1645056060.588 [CBIT](DEBUG): Backplane powered.
2022-02-17T00:01:00.589Z,1645056060.589 [MissionManager](INFO): Loading Mission from file: Missions/Startup_lab.xml
2022-02-17T00:01:00.607Z,1645056060.607 [Startup_lab:A.GoToSurface](DEBUG): Construct GoToSurface.
2022-02-17T00:01:00.660Z,1645056060.660 [Startup_lab:B.Wait](DEBUG): Construct Wait.
2022-02-17T00:01:00.663Z,1645056060.663 [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_lab">

    <Guidance:GoToSurface>
        <Progression/>
    </Guidance:GoToSurface>
    
    <Guidance:Wait>
        <Sequence/>
        <Setting><Guidance:Wait.duration/><Units:second/><Value>3</Value></Setting>
    </Guidance:Wait>

</Mission>


2022-02-17T00:01:00.663Z,1645056060.663 [MissionManager](INFO): Loading Mission from file: Missions/Default.xml
2022-02-17T00:01:00.768Z,1645056060.768 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2022-02-17T00:01:00.770Z,1645056060.770 [Default:A.Wait](DEBUG): Construct Wait.
2022-02-17T00:01:00.784Z,1645056060.784 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2022-02-17T00:01:00.857Z,1645056060.857 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2022-02-17T00:01:00.859Z,1645056060.859 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2022-02-17T00:01:00.886Z,1645056060.886 [Default:E.Execute](DEBUG): Construct Execute.
2022-02-17T00:01:00.901Z,1645056060.901 [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>


2022-02-17T00:01:00.906Z,1645056060.906 [controlThread](DEBUG): Component order: CycleStarter,PAR_Licor,AHRS_M2,BPC1,Depth_Keller,NAL9602,Power24vConverter,PAR_Licor,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,DeadReckonUsingSpeedCalculator,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterHE,SBIT,IBIT,CBIT,LcmUniversalReporter,Reporter,LogSplitter,
2022-02-17T00:01:00.912Z,1645056060.912 [Radio_Surface](INFO): Powering up
2022-02-17T00:01:00.933Z,1645056060.933 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2022-02-17T00:01:01.023Z,1645056061.023 [Power24vConverter](INFO): Powering up.
2022-02-17T00:01:01.139Z,1645056061.139 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2022-02-17T00:01:01.140Z,1645056061.140 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2022-02-17T00:01:01.141Z,1645056061.141 [ElevatorServo](DEBUG): Initializing EZServoServo.
2022-02-17T00:01:01.161Z,1645056061.161 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2022-02-17T00:01:01.162Z,1645056061.162 [MassServo](DEBUG): Initializing EZServoServo.
2022-02-17T00:01:01.165Z,1645056061.165 [MassServo](DEBUG): Initializing MassServo.
2022-02-17T00:01:01.166Z,1645056061.166 [RudderServo](DEBUG): Initializing EZServoServo.
2022-02-17T00:01:01.172Z,1645056061.172 [RudderServo](DEBUG): Initializing RudderServo.
2022-02-17T00:01:01.173Z,1645056061.173 [ThrusterHE](DEBUG): Initializing EZServoServo.
2022-02-17T00:01:01.184Z,1645056061.184 [ThrusterHE](DEBUG): Initializing ThrusterHE.
2022-02-17T00:01:02.036Z,1645056062.036 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2022-02-17T00:01:02.036Z,1645056062.036 [RudderServo](FAULT): Rudder failed to initialize
2022-02-17T00:01:02.036Z,1645056062.036 [RudderServo] Communications Fault, FailCount= 1
2022-02-17T00:01:02.036Z,1645056062.036 [RudderServo](ERROR): Communications Fault
2022-02-17T00:01:02.041Z,1645056062.041 [CBIT](ERROR): Communications Fault in component: RudderServo
2022-02-17T00:01:02.277Z,1645056062.277 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2022-02-17T00:01:02.277Z,1645056062.277 [RudderServo](INFO): Powering down
2022-02-17T00:01:02.953Z,1645056062.953 [RudderServo](DEBUG): Initializing EZServoServo.
2022-02-17T00:01:03.073Z,1645056063.073 [RudderServo](DEBUG): Initializing RudderServo.
2022-02-17T00:01:03.077Z,1645056063.077 [CBIT](INFO): Clearing failed state for component RudderServo
2022-02-17T00:01:03.077Z,1645056063.077 [RudderServo] No Fault, FailCount= 1
2022-02-17T00:01:03.080Z,1645056063.080 [WetLabsBB2FL](INFO): Powering down
2022-02-17T00:01:06.881Z,1645056066.881 [ThrusterHE](ERROR): Zero Speed Commanded.
2022-02-17T00:01:12.376Z,1645056072.376 [DAT](INFO): DAT read: 

2022-02-17T00:01:12.378Z,1645056072.378 [DAT](INFO): DAT read: Teledyne Benthos DAT-900 Series

2022-02-17T00:01:13.889Z,1645056073.889 [DAT](INFO): DAT read: MF Frequency Band

2022-02-17T00:01:13.890Z,1645056073.890 [DAT](INFO): DAT read: Directional Acoustic Transponder version 8.15.0

2022-02-17T00:01:13.891Z,1645056073.891 [DAT](INFO): DAT read: Feb 17 2022 00:01:08 

2022-02-17T00:01:14.897Z,1645056074.897 [DAT](INFO): DAT read: Features enabled [Bearing]

2022-02-17T00:01:14.898Z,1645056074.898 [DAT](INFO): DAT read: CONNECT 00800 bits/sec 1 of 4, Rate 1/2 CC 12.50ms MGP

2022-02-17T00:01:14.898Z,1645056074.898 [DAT](INFO): commRate: 800
2022-02-17T00:01:16.964Z,1645056076.964 [DAT](INFO): entering command mode
2022-02-17T00:01:17.164Z,1645056077.164 [DAT](INFO): DAT read: 

2022-02-17T00:01:17.165Z,1645056077.165 [DAT](INFO): DAT read: user:1>

2022-02-17T00:01:17.165Z,1645056077.165 [DAT](INFO): setting verbose to 3
2022-02-17T00:01:17.416Z,1645056077.416 [DAT](INFO): DAT read: user:1>

2022-02-17T00:01:17.418Z,1645056077.418 [DAT](INFO): DAT read: Verbose         | 3           

2022-02-17T00:01:17.418Z,1645056077.418 [DAT](INFO): set verbose to 3
2022-02-17T00:01:17.418Z,1645056077.418 [DAT](INFO): setting DatVerbose to 27440
2022-02-17T00:01:17.669Z,1645056077.669 [DAT](INFO): DAT read: user:2>

2022-02-17T00:01:17.670Z,1645056077.670 [DAT](INFO): DAT read: DatVerbose      | 27440       

2022-02-17T00:01:17.670Z,1645056077.670 [DAT](INFO): set DatVerbose to 27440
2022-02-17T00:01:17.670Z,1645056077.670 [DAT](INFO): setting transmit power to 8
2022-02-17T00:01:17.921Z,1645056077.921 [DAT](INFO): DAT read: user:3>

2022-02-17T00:01:17.922Z,1645056077.922 [DAT](INFO): DAT read: TxPower         | 8 (Max)     

2022-02-17T00:01:17.922Z,1645056077.922 [DAT](INFO): set transmit power to 8
2022-02-17T00:01:17.922Z,1645056077.922 [DAT](INFO): setting local address to 10
2022-02-17T00:01:18.172Z,1645056078.172 [DAT](INFO): DAT read: user:4>

2022-02-17T00:01:18.174Z,1645056078.174 [DAT](INFO): DAT read: LocalAddr       | 10          

2022-02-17T00:01:18.176Z,1645056078.176 [DAT](INFO): set local address to 10
2022-02-17T00:01:18.180Z,1645056078.180 [DAT](INFO): Setting time to: 0:1:18 And date to:2/17/2022
2022-02-17T00:01:18.425Z,1645056078.425 [DAT](INFO): DAT read: user:5>

2022-02-17T00:01:18.426Z,1645056078.426 [DAT](INFO): DAT read: Thu Feb 17, 2022  00:01:18  

2022-02-17T00:01:18.426Z,1645056078.426 [DAT](INFO): Local DAT time set to Thu Feb 17, 2022  00:01:18  

2022-02-17T00:01:24.057Z,1645056084.057 [CommandExec](IMPORTANT): got command show stack
2022-02-17T00:01:24.057Z,1645056084.057 [CommandExec](IMPORTANT): Behavior Stack:

2022-02-17T00:01:24.057Z,1645056084.057 [MissionManager](IMPORTANT): Mission loaded, but not running.
2022-02-17T00:01:30.011Z,1645056090.011 [NAL9602](INFO): Powering up NAL9602
2022-02-17T00:01:38.936Z,1645056098.936 [SBIT](IMPORTANT): Beginning Startup BIT
2022-02-17T00:01:38.944Z,1645056098.944 [CBIT](IMPORTANT): Beginning ground fault scan
2022-02-17T00:01:40.925Z,1645056100.925 [NAL9602](INFO): NAL9602 initialized
2022-02-17T00:01:49.880Z,1645056109.880 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.000940
CHAN A1 (24V): 0.001095
CHAN A2 (12V): -0.005787
CHAN A3 (5V): -0.002730
CHAN B0 (3.3V): -0.001140
CHAN B1 (3.15aV): -0.001340
CHAN B2 (3.15bV): -0.001397
CHAN B3 (GND): -0.000030
OPEN: 0.004547
Full Scale: +/- 1 mA
2022-02-17T00:02:15.205Z,1645056135.205 [CommandExec](IMPORTANT): got command show stack
2022-02-17T00:02:15.205Z,1645056135.205 [CommandExec](IMPORTANT): Behavior Stack:

2022-02-17T00:02:15.205Z,1645056135.205 [MissionManager](IMPORTANT): Mission loaded, but not running.
2022-02-17T00:02:33.055Z,1645056153.055 [SBIT](IMPORTANT): SBIT PASSED
2022-02-17T00:02:33.056Z,1645056153.056 [SBIT](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2022-02-17T00:02:33.057Z,1645056153.057 [SBIT](IMPORTANT): BackseatComponent.needs24v=1 bool;

2022-02-17T00:02:33.057Z,1645056153.057 [SBIT](IMPORTANT): BuoyancyServo.fastPumpCoefficient=6 none;

2022-02-17T00:02:33.059Z,1645056153.059 [SBIT](IMPORTANT): CBIT.gf24Offset=149 microampere;

2022-02-17T00:02:33.060Z,1645056153.060 [SBIT](IMPORTANT): DAT.sbdAddress=21 enum;

2022-02-17T00:02:33.060Z,1645056153.060 [SBIT](IMPORTANT): DAT.surfaceThreshold=3 meter;

2022-02-17T00:02:33.060Z,1645056153.060 [SBIT](IMPORTANT): DAT.verbosity=3 count;

2022-02-17T00:02:33.060Z,1645056153.060 [SBIT](IMPORTANT): DropWeight.loadAtStartup=0 bool;

2022-02-17T00:02:33.060Z,1645056153.060 [SBIT](IMPORTANT): Express linearApproximation _.ayeris_disk_space 10.000000 gigabyte;

2022-02-17T00:02:33.060Z,1645056153.060 [SBIT](IMPORTANT): Express linearApproximation _.ayeris_particle_counts 100.000000 count;

2022-02-17T00:02:33.061Z,1645056153.061 [SBIT](IMPORTANT): Express linearApproximation _.ayeris_particle_size 2.500000 millimeter;

2022-02-17T00:02:33.061Z,1645056153.061 [SBIT](IMPORTANT): Express linearApproximation _.eyeris_particle_counts 100.000000 count;

2022-02-17T00:02:33.061Z,1645056153.061 [SBIT](IMPORTANT): IBIT.batteryCapacityThreshold=5 ampere_hour;

2022-02-17T00:02:33.061Z,1645056153.061 [SBIT](IMPORTANT): IBIT.batteryVoltageThreshold=11 volt;

2022-02-17T00:02:33.061Z,1645056153.061 [SBIT](IMPORTANT): PowerOnly.loadAtStartup=0 bool;

2022-02-17T00:02:33.061Z,1645056153.061 [SBIT](IMPORTANT): VerticalControl.buoyancyNeutral=115.741138 cubic_centimeter;

2022-02-17T00:02:33.061Z,1645056153.061 [SBIT](IMPORTANT): VerticalControl.massDefault=-4.597572 millimeter;

2022-02-17T00:02:33.469Z,1645056153.469 [MissionManager](IMPORTANT): Started mission Startup_lab
2022-02-17T00:02:33.469Z,1645056153.469 [Startup_lab] Running Loop=1
2022-02-17T00:02:33.469Z,1645056153.469 [Startup_lab](DEBUG): Aggregate::initialize Startup_lab
2022-02-17T00:02:33.469Z,1645056153.469 [Startup_lab:A.GoToSurface] Running Loop=1
2022-02-17T00:02:33.469Z,1645056153.469 [Startup_lab:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2022-02-17T00:02:33.470Z,1645056153.470 [Startup_lab:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2022-02-17T00:02:33.470Z,1645056153.470 [Startup_lab:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2022-02-17T00:02:33.471Z,1645056153.471 [Startup_lab:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2022-02-17T00:02:33.471Z,1645056153.471 [Startup_lab:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2022-02-17T00:02:33.472Z,1645056153.472 [Startup_lab:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2022-02-17T00:02:33.473Z,1645056153.473 [Startup_lab:B.Wait] Running Loop=1
2022-02-17T00:02:33.473Z,1645056153.473 [Startup_lab:B.Wait](DEBUG): Initialize Wait Component.
2022-02-17T00:02:37.098Z,1645056157.098 [Startup_lab:B.Wait](INFO): Done Waiting.
2022-02-17T00:02:37.098Z,1645056157.098 [Startup_lab:B.Wait] Stopped
2022-02-17T00:02:37.098Z,1645056157.098 [Startup_lab:B.Wait](DEBUG): Uninitialize Wait Component.
2022-02-17T00:02:37.099Z,1645056157.099 [Startup_lab](INFO): Completed Startup_lab
2022-02-17T00:02:37.099Z,1645056157.099 [MissionManager](INFO): Startup_lab is completed.
2022-02-17T00:02:37.099Z,1645056157.099 [MissionManager](INFO): Uninitializing Mission Startup_lab
2022-02-17T00:02:37.099Z,1645056157.099 [Startup_lab] Stopped
2022-02-17T00:02:37.099Z,1645056157.099 [Startup_lab](DEBUG): Aggregate::uninitialize Startup_lab
2022-02-17T00:02:37.100Z,1645056157.100 [Startup_lab:A.GoToSurface] Stopped
2022-02-17T00:02:37.100Z,1645056157.100 [Startup_lab:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2022-02-17T00:02:37.548Z,1645056157.548 [MissionManager](IMPORTANT): Started mission Default
2022-02-17T00:02:37.548Z,1645056157.548 [Default] Running Loop=1
2022-02-17T00:02:37.549Z,1645056157.549 [Default](DEBUG): Aggregate::initialize Default
2022-02-17T00:02:37.549Z,1645056157.549 [Default:B.GoToSurface] Running Loop=1
2022-02-17T00:02:37.549Z,1645056157.549 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2022-02-17T00:02:37.549Z,1645056157.549 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2022-02-17T00:02:37.549Z,1645056157.549 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2022-02-17T00:02:37.550Z,1645056157.550 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2022-02-17T00:02:37.550Z,1645056157.550 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2022-02-17T00:02:37.550Z,1645056157.550 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2022-02-17T00:02:37.550Z,1645056157.550 [Default:A.Wait] Running Loop=1
2022-02-17T00:02:37.550Z,1645056157.550 [Default:A.Wait](DEBUG): Initialize Wait Component.
2022-02-17T00:02:50.838Z,1645056170.838 [Default:A.Wait](INFO): Done Waiting.
2022-02-17T00:02:50.838Z,1645056170.838 [Default:A.Wait] Stopped
2022-02-17T00:02:50.839Z,1645056170.839 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2022-02-17T00:02:51.227Z,1645056171.227 [Default:CheckIn] Running Loop=1
2022-02-17T00:02:51.227Z,1645056171.227 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-02-17T00:02:51.227Z,1645056171.227 [Default:CheckIn:Read_GPS] Running Loop=1
2022-02-17T00:02:51.658Z,1645056171.658 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2022-02-17T00:03:28.590Z,1645056208.590 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004912
2022-02-17T00:03:31.129Z,1645056211.129 [CommandExec](IMPORTANT): got command run ./Missions/Maintenance/tracking_on_surface.xml
2022-02-17T00:03:31.130Z,1645056211.130 [MissionManager](INFO): Loading Mission from file: ./Missions/Maintenance/tracking_on_surface.xml
2022-02-17T00:03:31.163Z,1645056211.163 [MissionManager](INFO): DefineArg tracking_on_surface.MissionTimeout = 60.000000 min
2022-02-17T00:03:31.166Z,1645056211.166 [MissionManager](INFO): DefineArg tracking_on_surface.ContactLabel = 201.000000 count
2022-02-17T00:03:31.169Z,1645056211.169 [MissionManager](INFO): DefineArg tracking_on_surface.NumberOfPings = 1.000000 count
2022-02-17T00:03:31.172Z,1645056211.172 [MissionManager](INFO): DefineArg tracking_on_surface.TrackingUpdatePeriod = 12.000000 s
2022-02-17T00:03:31.175Z,1645056211.175 [MissionManager](INFO): DefineArg tracking_on_surface.Repeat = 13.000000 count
2022-02-17T00:03:31.178Z,1645056211.178 [MissionManager](INFO): DefineArg tracking_on_surface.MassDefault = -0.459757 cm
2022-02-17T00:03:31.180Z,1645056211.180 [tracking_on_surface:A.Pitch](DEBUG): Construct.
2022-02-17T00:03:31.354Z,1645056211.354 [tracking_on_surface:TestDrive:A.Wait](DEBUG): Construct Wait.
2022-02-17T00:03:31.361Z,1645056211.361 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Derivation="Tethys/Estimation"
       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/Estimation http://okeanids.mbari.org/tethys/Xml/Estimation.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="tracking_on_surface">

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

    <DefineArg Name="ContactLabel"><Units:count/><Value>201</Value></DefineArg>

    <DefineArg Name="NumberOfPings"><Units:count/><Value>1</Value></DefineArg>

    <DefineArg Name="TrackingUpdatePeriod"><Units:second/><Value>12</Value></DefineArg>

    <DefineArg Name="Repeat"><Units:count/><Value>13</Value></DefineArg>

    <DefineArg Name="MassDefault"><Control:VerticalControl.massDefault/></DefineArg>

    <Timeout Duration="MissionTimeout"/>

    <Guidance:Pitch>
        <Parallel/>
        <Setting><Guidance:Pitch.massPosition/><Arg Name="MassDefault"/></Setting>
    </Guidance:Pitch>

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

    <Aggregate Id="TestDrive">

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

    </Aggregate>

</Mission>


2022-02-17T00:03:31.363Z,1645056211.363 [CommandExec](IMPORTANT): Running ./Missions/Maintenance/tracking_on_surface.xml
2022-02-17T00:03:31.647Z,1645056211.647 [Default] Stopped
2022-02-17T00:03:31.647Z,1645056211.647 [Default](DEBUG): Aggregate::uninitialize Default
2022-02-17T00:03:31.648Z,1645056211.648 [Default:B.GoToSurface] Stopped
2022-02-17T00:03:31.648Z,1645056211.648 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2022-02-17T00:03:31.648Z,1645056211.648 [Default:CheckIn] Stopped
2022-02-17T00:03:31.648Z,1645056211.648 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-02-17T00:03:31.648Z,1645056211.648 [Default:CheckIn:Read_GPS] Stopped
2022-02-17T00:03:31.648Z,1645056211.648 [MissionManager](IMPORTANT): Started mission tracking_on_surface
2022-02-17T00:03:31.648Z,1645056211.648 [tracking_on_surface] Running Loop=1
2022-02-17T00:03:31.649Z,1645056211.649 [tracking_on_surface](DEBUG): Aggregate::initialize tracking_on_surface
2022-02-17T00:03:31.649Z,1645056211.649 [tracking_on_surface:A.Pitch] Running Loop=1
2022-02-17T00:03:31.649Z,1645056211.649 [tracking_on_surface:A.Pitch](DEBUG): Initialize.
2022-02-17T00:03:31.649Z,1645056211.649 [tracking_on_surface:B.] Running Loop=1
2022-02-17T00:03:31.649Z,1645056211.649 [tracking_on_surface:B.](INFO): Initializing TrackAcousticContact.
2022-02-17T00:03:31.649Z,1645056211.649 [tracking_on_surface:TestDrive] Running Loop=1
2022-02-17T00:03:31.650Z,1645056211.650 [tracking_on_surface:TestDrive](DEBUG): Aggregate::initialize tracking_on_surface:TestDrive
2022-02-17T00:03:31.650Z,1645056211.650 [tracking_on_surface:TestDrive:A.Wait] Running Loop=1
2022-02-17T00:03:31.650Z,1645056211.650 [tracking_on_surface:TestDrive:A.Wait](DEBUG): Initialize Wait Component.
2022-02-17T00:03:31.650Z,1645056211.650 [tracking_on_surface:B.] Running Loop=1
2022-02-17T00:03:31.650Z,1645056211.650 [tracking_on_surface:B.](DEBUG): Tracking...
2022-02-17T00:03:31.651Z,1645056211.651 [tracking_on_surface:B.](INFO): Tracking contact label: 201
2022-02-17T00:03:31.652Z,1645056211.652 [tracking_on_surface:B.](INFO): waiting for update period (12.000000 s) to elapse
2022-02-17T00:03:31.652Z,1645056211.652 [tracking_on_surface:A.Pitch] Running Loop=1
2022-02-17T00:03:32.037Z,1645056212.037 [tracking_on_surface:B.](DEBUG): Tracking...
2022-02-17T00:03:32.037Z,1645056212.037 [tracking_on_surface:B.](INFO): Tracking contact label: 201
2022-02-17T00:03:32.038Z,1645056212.038 [tracking_on_surface:B.](INFO): waiting for update period (12.000000 s) to elapse
2022-02-17T00:03:32.426Z,1645056212.426 [tracking_on_surface:B.](DEBUG): Tracking...
2022-02-17T00:03:32.427Z,1645056212.427 [tracking_on_surface:B.](INFO): Tracking contact label: 201
2022-02-17T00:03:32.427Z,1645056212.427 [tracking_on_surface:B.](INFO): waiting for update period (12.000000 s) to elapse
2022-02-17T00:03:32.843Z,1645056212.843 [tracking_on_surface:B.](DEBUG): Tracking...
2022-02-17T00:03:32.844Z,1645056212.844 [tracking_on_surface:B.](INFO): Tracking contact label: 201
2022-02-17T00:03:32.845Z,1645056212.845 [tracking_on_surface:B.](INFO): waiting for update period (12.000000 s) to elapse
2022-02-17T00:03:33.258Z,1645056213.258 [tracking_on_surface:B.](DEBUG): Tracking...
2022-02-17T00:03:33.259Z,1645056213.259 [tracking_on_surface:B.](INFO): Tracking contact label: 201
2022-02-17T00:03:33.259Z,1645056213.259 [tracking_on_surface:B.](INFO): waiting for update period (12.000000 s) to elapse
2022-02-17T00:03:33.659Z,1645056213.659 [tracking_on_surface:B.](DEBUG): Tracking...
2022-02-17T00:03:33.676Z,1645056213.676 [tracking_on_surface:B.](INFO): Tracking contact label: 201
2022-02-17T00:03:33.676Z,1645056213.676 [tracking_on_surface:B.](INFO): waiting for update period (12.000000 s) to elapse
2022-02-17T00:03:34.062Z,1645056214.062 [tracking_on_surface:B.](DEBUG): Tracking...
2022-02-17T00:03:34.062Z,1645056214.062 [tracking_on_surface:B.](INFO): Tracking contact label: 201
2022-02-17T00:03:34.063Z,1645056214.063 [tracking_on_surface:B.](INFO): waiting for update period (12.000000 s) to elapse
2022-02-17T00:03:34.478Z,1645056214.478 [tracking_on_surface:B.](DEBUG): Tracking...
2022-02-17T00:03:34.478Z,1645056214.478 [tracking_on_surface:B.](INFO): Tracking contact label: 201
2022-02-17T00:03:34.479Z,1645056214.479 [tracking_on_surface:B.](INFO): waiting for update period (12.000000 s) to elapse
2022-02-17T00:03:34.882Z,1645056214.882 [tracking_on_surface:B.](DEBUG): Tracking...
2022-02-17T00:03:34.882Z,1645056214.882 [tracking_on_surface:B.](INFO): Tracking contact label: 201
2022-02-17T00:03:34.883Z,1645056214.883 [tracking_on_surface:B.](INFO): waiting for update period (12.000000 s) to elapse
2022-02-17T00:03:35.260Z,1645056215.260 [tracking_on_surface:B.](DEBUG): Tracking...
2022-02-17T00:03:35.261Z,1645056215.261 [tracking_on_surface:B.](INFO): Tracking contact label: 201
2022-02-17T00:03:35.261Z,1645056215.261 [tracking_on_surface:B.](INFO): waiting for update period (12.000000 s) to elapse
2022-02-17T00:03:35.677Z,1645056215.677 [tracking_on_surface:B.](DEBUG): Tracking...
2022-02-17T00:03:35.677Z,1645056215.677 [tracking_on_surface:B.](INFO): Tracking contact label: 201
2022-02-17T00:03:35.677Z,1645056215.677 [tracking_on_surface:B.](INFO): waiting for update period (12.000000 s) to elapse
2022-02-17T00:03:36.079Z,1645056216.079 [tracking_on_surface:B.](DEBUG): Tracking...
2022-02-17T00:03:36.079Z,1645056216.079 [tracking_on_surface:B.](INFO): Tracking contact label: 201
2022-02-17T00:03:36.080Z,1645056216.080 [tracking_on_surface:B.](INFO): waiting for update period (12.000000 s) to elapse
2022-02-17T00:03:36.472Z,1645056216.472 [tracking_on_surface:B.](DEBUG): Tracking...
2022-02-17T00:03:36.473Z,1645056216.473 [tracking_on_surface:B.](INFO): Tracking contact label: 201
2022-02-17T00:03:36.473Z,1645056216.473 [tracking_on_surface:B.](INFO): waiting for update period (12.000000 s) to elapse
2022-02-17T00:03:36.876Z,1645056216.876 [tracking_on_surface:B.](DEBUG): Tracking...
2022-02-17T00:03:36.877Z,1645056216.877 [tracking_on_surface:B.](INFO): Tracking contact label: 201
2022-02-17T00:03:36.877Z,1645056216.877 [tracking_on_surface:B.](INFO): waiting for update period (12.000000 s) to elapse
2022-02-17T00:03:37.285Z,1645056217.285 [tracking_on_surface:B.](DEBUG): Tracking...
2022-02-17T00:03:37.285Z,1645056217.285 [tracking_on_surface:B.](INFO): Tracking contact label: 201
2022-02-17T00:03:37.286Z,1645056217.286 [tracking_on_surface:B.](INFO): waiting for update period (12.000000 s) to elapse
2022-02-17T00:03:37.695Z,1645056217.695 [tracking_on_surface:B.](DEBUG): Tracking...
2022-02-17T00:03:37.695Z,1645056217.695 [tracking_on_surface:B.](INFO): Tracking contact label: 201
2022-02-17T00:03:37.696Z,1645056217.696 [tracking_on_surface:B.](INFO): waiting for update period (12.000000 s) to elapse
2022-02-17T00:03:38.086Z,1645056218.086 [tracking_on_surface:B.](DEBUG): Tracking...
2022-02-17T00:03:38.086Z,1645056218.086 [tracking_on_surface:B.](INFO): Tracking contact label: 201
2022-02-17T00:03:38.086Z,1645056218.086 [tracking_on_surface:B.](INFO): waiting for update period (12.000000 s) to elapse
2022-02-17T00:03:38.487Z,1645056218.487 [tracking_on_surface:B.](DEBUG): Tracking...
2022-02-17T00:03:38.487Z,1645056218.487 [tracking_on_surface:B.](INFO): Tracking contact label: 201
2022-02-17T00:03:38.488Z,1645056218.488 [tracking_on_surface:B.](INFO): waiting for update period (12.000000 s) to elapse
2022-02-17T00:03:38.914Z,1645056218.914 [tracking_on_surface:B.](DEBUG): Tracking...
2022-02-17T00:03:38.914Z,1645056218.914 [tracking_on_surface:B.](INFO): Tracking contact label: 201
2022-02-17T00:03:38.915Z,1645056218.915 [tracking_on_surface:B.](INFO): waiting for update period (12.000000 s) to elapse
2022-02-17T00:03:39.311Z,1645056219.311 [tracking_on_surface:B.](DEBUG): Tracking...
2022-02-17T00:03:39.311Z,1645056219.311 [tracking_on_surface:B.](INFO): Tracking contact label: 201
2022-02-17T00:03:39.312Z,1645056219.312 [tracking_on_surface:B.](INFO): waiting for update period (12.000000 s) to elapse
2022-02-17T00:03:39.742Z,1645056219.742 [tracking_on_surface:B.](DEBUG): Tracking...
2022-02-17T00:03:39.742Z,1645056219.742 [tracking_on_surface:B.](INFO): Tracking contact label: 201
2022-02-17T00:03:39.743Z,1645056219.743 [tracking_on_surface:B.](INFO): waiting for update period (12.000000 s) to elapse
2022-02-17T00:03:40.193Z,1645056220.193 [tracking_on_surface:B.](DEBUG): Tracking...
2022-02-17T00:03:40.194Z,1645056220.194 [tracking_on_surface:B.](INFO): Tracking contact label: 201
2022-02-17T00:03:40.194Z,1645056220.194 [tracking_on_surface:B.](INFO): waiting for update period (12.000000 s) to elapse
2022-02-17T00:03:40.521Z,1645056220.521 [tracking_on_surface:B.](DEBUG): Tracking...
2022-02-17T00:03:40.521Z,1645056220.521 [tracking_on_surface:B.](INFO): Tracking contact label: 201
2022-02-17T00:03:40.522Z,1645056220.522 [tracking_on_surface:B.](INFO): waiting for update period (12.000000 s) to elapse
2022-02-17T00:03:40.932Z,1645056220.932 [tracking_on_surface:B.](DEBUG): Tracking...
2022-02-17T00:03:40.932Z,1645056220.932 [tracking_on_surface:B.](INFO): Tracking contact label: 201
2022-02-17T00:03:40.933Z,1645056220.933 [tracking_on_surface:B.](INFO): waiting for update period (12.000000 s) to elapse
2022-02-17T00:03:41.339Z,1645056221.339 [tracking_on_surface:B.](DEBUG): Tracking...
2022-02-17T00:03:41.339Z,1645056221.339 [tracking_on_surface:B.](INFO): Tracking contact label: 201
2022-02-17T00:03:41.340Z,1645056221.340 [tracking_on_surface:B.](INFO): waiting for update period (12.000000 s) to elapse
2022-02-17T00:03:41.724Z,1645056221.724 [tracking_on_surface:B.](DEBUG): Tracking...
2022-02-17T00:03:41.725Z,1645056221.725 [tracking_on_surface:B.](INFO): Tracking contact label: 201
2022-02-17T00:03:41.725Z,1645056221.725 [tracking_on_surface:B.](INFO): waiting for update period (12.000000 s) to elapse
2022-02-17T00:03:42.192Z,1645056222.192 [tracking_on_surface:B.](DEBUG): Tracking...
2022-02-17T00:03:42.193Z,1645056222.193 [tracking_on_surface:B.](INFO): Tracking contact label: 201
2022-02-17T00:03:42.193Z,1645056222.193 [tracking_on_surface:B.](INFO): waiting for update period (12.000000 s) to elapse
2022-02-17T00:03:42.553Z,1645056222.553 [tracking_on_surface:B.](DEBUG): Tracking...
2022-02-17T00:03:42.553Z,1645056222.553 [tracking_on_surface:B.](INFO): Tracking contact label: 201
2022-02-17T00:03:42.554Z,1645056222.554 [tracking_on_surface:B.](INFO): waiting for update period (12.000000 s) to elapse
2022-02-17T00:03:42.962Z,1645056222.962 [tracking_on_surface:B.](DEBUG): Tracking...
2022-02-17T00:03:42.962Z,1645056222.962 [tracking_on_surface:B.](INFO): Tracking contact label: 201
2022-02-17T00:03:42.963Z,1645056222.963 [tracking_on_surface:B.](INFO): waiting for update period (12.000000 s) to elapse
2022-02-17T00:03:43.353Z,1645056223.353 [tracking_on_surface:B.](DEBUG): Tracking...
2022-02-17T00:03:43.353Z,1645056223.353 [tracking_on_surface:B.](INFO): Tracking contact label: 201
2022-02-17T00:03:43.354Z,1645056223.354 [tracking_on_surface:B.](INFO): waiting for update period (12.000000 s) to elapse
2022-02-17T00:03:43.740Z,1645056223.740 [tracking_on_surface:B.](DEBUG): Tracking...
2022-02-17T00:03:43.741Z,1645056223.741 [tracking_on_surface:B.](INFO): Tracking contact label: 201
2022-02-17T00:03:43.741Z,1645056223.741 [tracking_on_surface:B.](INFO): update period (12.000000 s) has elapsed, querying...
2022-02-17T00:03:43.741Z,1645056223.741 [tracking_on_surface:B.](INFO): *** querying acoustic contact ***
2022-02-17T00:03:43.785Z,1645056223.785 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:03:43.785Z,1645056223.785 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:03:43.785Z,1645056223.785 [DAT](INFO): setting remote address to 0
2022-02-17T00:03:44.036Z,1645056224.036 [DAT](INFO): DAT read: user:6>

2022-02-17T00:03:44.037Z,1645056224.037 [DAT](INFO): DAT read: RemoteAddr      | 0           

2022-02-17T00:03:44.038Z,1645056224.038 [DAT](INFO): set remote address to 0
2022-02-17T00:03:44.038Z,1645056224.038 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:03:44.038Z,1645056224.038 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:03:44.039Z,1645056224.039 [DAT](INFO): Querying Benthos address 201 with one ping in standard two-way mode.
2022-02-17T00:03:44.168Z,1645056224.168 [tracking_on_surface:B.](DEBUG): Tracking...
2022-02-17T00:03:44.169Z,1645056224.169 [tracking_on_surface:B.](INFO): Tracking contact label: 201
2022-02-17T00:03:44.169Z,1645056224.169 [tracking_on_surface:B.](INFO): waiting for update period (12.000000 s) to elapse
2022-02-17T00:03:44.288Z,1645056224.288 [DAT](INFO): DAT read: user:7>

2022-02-17T00:03:44.289Z,1645056224.289 [DAT](INFO): DAT read: Tx time:00:03:44.0215

2022-02-17T00:03:44.290Z,1645056224.290 [DAT](INFO): Ping request sent.
2022-02-17T00:03:44.290Z,1645056224.290 [DAT](INFO): transmitted an acoustic signal
2022-02-17T00:03:44.290Z,1645056224.290 [DAT](INFO): publishing transmit ping time
2022-02-17T00:03:44.291Z,1645056224.291 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=0.001231
2022-02-17T00:03:44.541Z,1645056224.541 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=0.250874
2022-02-17T00:03:44.587Z,1645056224.587 [tracking_on_surface:B.](DEBUG): Tracking...
2022-02-17T00:03:44.587Z,1645056224.587 [tracking_on_surface:B.](INFO): Tracking contact label: 201
2022-02-17T00:03:44.588Z,1645056224.588 [tracking_on_surface:B.](INFO): waiting for update period (12.000000 s) to elapse
2022-02-17T00:03:44.613Z,1645056224.613 [CommandExec](IMPORTANT): got command stop
2022-02-17T00:03:44.613Z,1645056224.613 [CommandExec](IMPORTANT): Scheduling is paused
2022-02-17T00:03:44.613Z,1645056224.613 [Supervisor](INFO): Stop Mission called by CommandExec::commandStop
2022-02-17T00:03:44.793Z,1645056224.793 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=0.502847
2022-02-17T00:03:44.978Z,1645056224.978 [tracking_on_surface:B.](DEBUG): Tracking...
2022-02-17T00:03:44.978Z,1645056224.978 [tracking_on_surface:B.](INFO): Tracking contact label: 201
2022-02-17T00:03:44.979Z,1645056224.979 [tracking_on_surface:B.](INFO): waiting for update period (12.000000 s) to elapse
2022-02-17T00:03:44.979Z,1645056224.979 [MissionManager](INFO): MissionManager is completed.
2022-02-17T00:03:44.979Z,1645056224.979 [MissionManager](INFO): Uninitializing Mission tracking_on_surface
2022-02-17T00:03:45.018Z,1645056225.018 [tracking_on_surface] Stopped
2022-02-17T00:03:45.018Z,1645056225.018 [tracking_on_surface](DEBUG): Aggregate::uninitialize tracking_on_surface
2022-02-17T00:03:45.018Z,1645056225.018 [tracking_on_surface:A.Pitch] Stopped
2022-02-17T00:03:45.018Z,1645056225.018 [tracking_on_surface:B.] Stopped
2022-02-17T00:03:45.018Z,1645056225.018 [tracking_on_surface:B.](DEBUG): Uninitializing TrackAcousticContact.
2022-02-17T00:03:45.018Z,1645056225.018 [tracking_on_surface:TestDrive] Stopped
2022-02-17T00:03:45.018Z,1645056225.018 [tracking_on_surface:TestDrive](DEBUG): Aggregate::uninitialize tracking_on_surface:TestDrive
2022-02-17T00:03:45.018Z,1645056225.018 [tracking_on_surface:TestDrive:A.Wait] Stopped
2022-02-17T00:03:45.018Z,1645056225.018 [tracking_on_surface:TestDrive:A.Wait](DEBUG): Uninitialize Wait Component.
2022-02-17T00:03:45.045Z,1645056225.045 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=0.755299
2022-02-17T00:03:45.300Z,1645056225.300 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=1.009320
2022-02-17T00:03:45.390Z,1645056225.390 [MissionManager](IMPORTANT): Started mission Default
2022-02-17T00:03:45.390Z,1645056225.390 [Default] Running Loop=1
2022-02-17T00:03:45.390Z,1645056225.390 [Default](DEBUG): Aggregate::initialize Default
2022-02-17T00:03:45.390Z,1645056225.390 [Default:B.GoToSurface] Running Loop=1
2022-02-17T00:03:45.390Z,1645056225.390 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2022-02-17T00:03:45.391Z,1645056225.391 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2022-02-17T00:03:45.391Z,1645056225.391 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2022-02-17T00:03:45.391Z,1645056225.391 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2022-02-17T00:03:45.392Z,1645056225.392 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2022-02-17T00:03:45.392Z,1645056225.392 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2022-02-17T00:03:45.392Z,1645056225.392 [Default:A.Wait] Running Loop=1
2022-02-17T00:03:45.392Z,1645056225.392 [Default:A.Wait](DEBUG): Initialize Wait Component.
2022-02-17T00:03:45.549Z,1645056225.549 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=1.259282
2022-02-17T00:03:45.801Z,1645056225.801 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=1.511130
2022-02-17T00:03:46.053Z,1645056226.053 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=1.762914
2022-02-17T00:03:46.305Z,1645056226.305 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=2.014845
2022-02-17T00:03:46.557Z,1645056226.557 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=2.267285
2022-02-17T00:03:46.809Z,1645056226.809 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=2.518884
2022-02-17T00:03:47.061Z,1645056227.061 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=2.770804
2022-02-17T00:03:47.313Z,1645056227.313 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=3.023061
2022-02-17T00:03:47.565Z,1645056227.565 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=3.274905
2022-02-17T00:03:47.817Z,1645056227.817 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=3.526997
2022-02-17T00:03:48.069Z,1645056228.069 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=3.779143
2022-02-17T00:03:48.321Z,1645056228.321 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=4.030935
2022-02-17T00:03:48.574Z,1645056228.574 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=4.284008
2022-02-17T00:03:48.825Z,1645056228.825 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=4.535058
2022-02-17T00:03:49.077Z,1645056229.077 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=4.786928
2022-02-17T00:03:49.329Z,1645056229.329 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=5.038878
2022-02-17T00:03:49.581Z,1645056229.581 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=5.291129
2022-02-17T00:03:49.833Z,1645056229.833 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=5.543005
2022-02-17T00:03:50.086Z,1645056230.086 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=5.796095
2022-02-17T00:03:50.337Z,1645056230.337 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=6.047081
2022-02-17T00:03:50.589Z,1645056230.589 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=6.298901
2022-02-17T00:03:50.841Z,1645056230.841 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=6.550885
2022-02-17T00:03:51.093Z,1645056231.093 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=6.803126
2022-02-17T00:03:51.345Z,1645056231.345 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=7.054916
2022-02-17T00:03:51.596Z,1645056231.596 [DAT](INFO): DAT read: 

2022-02-17T00:03:51.597Z,1645056231.597 [DAT](INFO): DAT read: Teledyne Benthos DAT-900 Series

2022-02-17T00:03:51.598Z,1645056231.598 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=7.308091
2022-02-17T00:03:51.849Z,1645056231.849 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=7.559213
2022-02-17T00:03:52.101Z,1645056232.101 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=7.810908
2022-02-17T00:03:52.353Z,1645056232.353 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=8.062951
2022-02-17T00:03:52.605Z,1645056232.605 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=8.315078
2022-02-17T00:03:52.857Z,1645056232.857 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=8.566879
2022-02-17T00:03:53.109Z,1645056233.109 [DAT](INFO): DAT read: MF Frequency Band

2022-02-17T00:03:53.110Z,1645056233.110 [DAT](INFO): DAT read: Directional Acoustic Transponder version 8.15.0

2022-02-17T00:03:53.111Z,1645056233.111 [DAT](INFO): DAT read: Feb 17 2022 00:03:48 

2022-02-17T00:03:53.111Z,1645056233.111 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=8.821499
2022-02-17T00:03:53.361Z,1645056233.361 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=9.071173
2022-02-17T00:03:53.613Z,1645056233.613 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=9.322869
2022-02-17T00:03:53.865Z,1645056233.865 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=9.574875
2022-02-17T00:03:54.117Z,1645056234.117 [DAT](INFO): DAT read: Features enabled [Bearing]

2022-02-17T00:03:54.119Z,1645056234.119 [DAT](INFO): DAT read: WARNING: Modem reset during xmit; lowering xmit power level by 3 dB.

2022-02-17T00:03:54.120Z,1645056234.120 [DAT](INFO): unknown deviceResponse_: WARNING: Modem reset during xmit; lowering xmit power level by 3 dB.

2022-02-17T00:03:54.122Z,1645056234.122 [DAT](INFO): DAT read: WARNING: Reduced xmit power level to 7 due to weak battery.

2022-02-17T00:03:54.122Z,1645056234.122 [DAT](INFO): unknown deviceResponse_: WARNING: Reduced xmit power level to 7 due to weak battery.

2022-02-17T00:03:54.123Z,1645056234.123 [DAT](INFO): DAT read: CONNECT 00800 bits/sec 1 of 4, Rate 1/2 CC 12.50ms MGP

2022-02-17T00:03:54.124Z,1645056234.124 [DAT](INFO): commRate: 800
2022-02-17T00:03:54.124Z,1645056234.124 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=9.834718
2022-02-17T00:03:58.693Z,1645056238.693 [Default:A.Wait](INFO): Done Waiting.
2022-02-17T00:03:58.693Z,1645056238.693 [Default:A.Wait] Stopped
2022-02-17T00:03:58.693Z,1645056238.693 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2022-02-17T00:03:59.117Z,1645056239.117 [Default:CheckIn] Running Loop=1
2022-02-17T00:03:59.117Z,1645056239.117 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-02-17T00:03:59.117Z,1645056239.117 [Default:CheckIn:Read_GPS] Running Loop=1
2022-02-17T00:04:00.751Z,1645056240.751 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2022-02-17T00:04:00.751Z,1645056240.751 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2022-02-17T00:04:00.752Z,1645056240.752 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 1
2022-02-17T00:04:00.752Z,1645056240.752 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2022-02-17T00:04:00.771Z,1645056240.771 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2022-02-17T00:04:00.771Z,1645056240.771 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2022-02-17T00:04:01.167Z,1645056241.167 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2022-02-17T00:04:01.167Z,1645056241.167 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2022-02-17T00:04:01.167Z,1645056241.167 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2022-02-17T00:04:01.167Z,1645056241.167 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 1
2022-02-17T00:04:01.532Z,1645056241.532 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2022-02-17T00:04:09.289Z,1645056249.289 [CommandExec](IMPORTANT): got command strobe off
2022-02-17T00:04:09.289Z,1645056249.289 [CommandExec](IMPORTANT): Deactivating strobe
2022-02-17T00:06:43.928Z,1645056403.928 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2022-02-17T00:07:01.739Z,1645056421.739 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2
2022-02-17T00:07:01.744Z,1645056421.744 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2022-02-17T00:07:01.745Z,1645056421.745 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 2
2022-02-17T00:07:01.745Z,1645056421.745 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2022-02-17T00:07:01.769Z,1645056421.769 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2022-02-17T00:07:01.770Z,1645056421.770 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2022-02-17T00:07:02.132Z,1645056422.132 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2022-02-17T00:07:02.132Z,1645056422.132 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2
2022-02-17T00:07:02.132Z,1645056422.132 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2022-02-17T00:07:02.132Z,1645056422.132 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 2
2022-02-17T00:07:02.526Z,1645056422.526 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2022-02-17T00:08:56.432Z,1645056536.432 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2022-02-17T00:08:56.434Z,1645056536.434 [BPC1](INFO): Received data from all battery sticks.
2022-02-17T00:08:59.265Z,1645056539.265 [Default:CheckIn:Read_GPS](INFO): Timed out from 2022-02-17T00:03:59.1Z
2022-02-17T00:08:59.265Z,1645056539.265 [Default:CheckIn:Read_GPS] Stopped
2022-02-17T00:08:59.266Z,1645056539.266 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-02-17T00:08:59.680Z,1645056539.680 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2022-02-17T00:09:06.364Z,1645056546.364 [DataOverHttps](INFO): Sending 151 bytes from file Logs/20220216T222636/Courier0000.lzma
2022-02-17T00:09:07.378Z,1645056547.378 [DataOverHttps](INFO): Moved sent file to Logs/20220216T222636/Courier0000.lzma.bak
2022-02-17T00:09:07.378Z,1645056547.378 [DataOverHttps](INFO): SBD MOMSN=16504293
2022-02-17T00:09:22.995Z,1645056562.995 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20220216T222636/Courier0004.lzma
2022-02-17T00:09:23.998Z,1645056563.998 [DataOverHttps](INFO): Moved sent file to Logs/20220216T222636/Courier0004.lzma.bak
2022-02-17T00:09:23.998Z,1645056563.998 [DataOverHttps](INFO): SBD MOMSN=16504296
2022-02-17T00:09:39.568Z,1645056579.568 [DataOverHttps](INFO): Sending 247 bytes from file Logs/20220216T223859/Courier0000.lzma
2022-02-17T00:09:40.570Z,1645056580.570 [DataOverHttps](INFO): Moved sent file to Logs/20220216T223859/Courier0000.lzma.bak
2022-02-17T00:09:40.570Z,1645056580.570 [DataOverHttps](INFO): SBD MOMSN=16504298
2022-02-17T00:09:56.123Z,1645056596.123 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20220216T224124/Courier0000.lzma
2022-02-17T00:09:57.125Z,1645056597.125 [DataOverHttps](INFO): Moved sent file to Logs/20220216T224124/Courier0000.lzma.bak
2022-02-17T00:09:57.126Z,1645056597.126 [DataOverHttps](INFO): SBD MOMSN=16504303
2022-02-17T00:10:02.703Z,1645056602.703 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 3
2022-02-17T00:10:02.703Z,1645056602.703 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2022-02-17T00:10:02.728Z,1645056602.728 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 3
2022-02-17T00:10:02.728Z,1645056602.728 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2022-02-17T00:10:02.747Z,1645056602.747 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2022-02-17T00:10:02.747Z,1645056602.747 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2022-02-17T00:10:03.144Z,1645056603.144 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2022-02-17T00:10:03.144Z,1645056603.144 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 3
2022-02-17T00:10:03.145Z,1645056603.145 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2022-02-17T00:10:03.145Z,1645056603.145 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 3
2022-02-17T00:10:03.498Z,1645056603.498 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2022-02-17T00:10:12.924Z,1645056612.924 [DataOverHttps](INFO): Sending 208 bytes from file Logs/20220216T235948/Courier0000.lzma
2022-02-17T00:10:13.926Z,1645056613.926 [DataOverHttps](INFO): Moved sent file to Logs/20220216T235948/Courier0000.lzma.bak
2022-02-17T00:10:13.926Z,1645056613.926 [DataOverHttps](INFO): SBD MOMSN=16504306
2022-02-17T00:10:29.456Z,1645056629.456 [DataOverHttps](INFO): Sending 194 bytes from file Logs/20220217T000050/Courier0000.lzma
2022-02-17T00:10:30.457Z,1645056630.457 [DataOverHttps](INFO): Moved sent file to Logs/20220217T000050/Courier0000.lzma.bak
2022-02-17T00:10:30.458Z,1645056630.458 [DataOverHttps](INFO): SBD MOMSN=16504310
2022-02-17T00:10:46.014Z,1645056646.014 [DataOverHttps](INFO): Sending 1162 bytes from file Logs/20220127T201417/Express0001.lzma
2022-02-17T00:10:47.013Z,1645056647.013 [DataOverHttps](INFO): Moved sent file to Logs/20220127T201417/Express0001.lzma.bak
2022-02-17T00:10:47.014Z,1645056647.014 [DataOverHttps](INFO): SBD MOMSN=16504313
2022-02-17T00:11:05.188Z,1645056665.188 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20220216T221605/Express0001.lzma
2022-02-17T00:11:06.198Z,1645056666.198 [DataOverHttps](INFO): Moved sent file to Logs/20220216T221605/Express0001.lzma.bak
2022-02-17T00:11:06.198Z,1645056666.198 [DataOverHttps](INFO): SBD MOMSN=16504352
2022-02-17T00:11:23.829Z,1645056683.829 [DataOverHttps](INFO): Sending 1051 bytes from file Logs/20220216T221933/Express0001.lzma
2022-02-17T00:11:24.829Z,1645056684.829 [DataOverHttps](INFO): Moved sent file to Logs/20220216T221933/Express0001.lzma.bak
2022-02-17T00:11:24.830Z,1645056684.830 [DataOverHttps](INFO): SBD MOMSN=16504354
2022-02-17T00:11:40.580Z,1645056700.580 [DataOverHttps](INFO): Sending 231 bytes from file Logs/20220216T221933/Express0005.lzma
2022-02-17T00:11:41.582Z,1645056701.582 [DataOverHttps](INFO): Moved sent file to Logs/20220216T221933/Express0005.lzma.bak
2022-02-17T00:11:41.582Z,1645056701.582 [DataOverHttps](INFO): SBD MOMSN=16504386
2022-02-17T00:11:44.137Z,1645056704.137 [NAL9602](FAULT): GPS failed to acquire within timeout.
2022-02-17T00:11:44.137Z,1645056704.137 [NAL9602] Data Fault, FailCount= 1
2022-02-17T00:11:44.137Z,1645056704.137 [NAL9602](ERROR): Data Fault
2022-02-17T00:11:44.158Z,1645056704.158 [CBIT](ERROR): Data Fault in component: NAL9602
2022-02-17T00:11:44.550Z,1645056704.550 [NAL9602](INFO): Powering down
2022-02-17T00:11:45.415Z,1645056705.415 [CBIT](INFO): Clearing failed state for component NAL9602
2022-02-17T00:11:45.415Z,1645056705.415 [NAL9602] No Fault, FailCount= 1
2022-02-17T00:11:57.173Z,1645056717.173 [DataOverHttps](INFO): Sending 1002 bytes from file Logs/20220216T222636/Express0001.lzma
2022-02-17T00:11:58.173Z,1645056718.173 [DataOverHttps](INFO): Moved sent file to Logs/20220216T222636/Express0001.lzma.bak
2022-02-17T00:11:58.174Z,1645056718.174 [DataOverHttps](INFO): SBD MOMSN=16504395
2022-02-17T00:12:13.628Z,1645056733.628 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20220216T222636/Express0005.lzma
2022-02-17T00:12:14.630Z,1645056734.630 [DataOverHttps](INFO): Moved sent file to Logs/20220216T222636/Express0005.lzma.bak
2022-02-17T00:12:14.630Z,1645056734.630 [DataOverHttps](INFO): SBD MOMSN=16504423
2022-02-17T00:12:14.834Z,1645056734.834 [NAL9602](INFO): Powering up NAL9602
2022-02-17T00:12:25.746Z,1645056745.746 [NAL9602](INFO): NAL9602 initialized
2022-02-17T00:12:30.149Z,1645056750.149 [DataOverHttps](INFO): Sending 802 bytes from file Logs/20220216T223859/Express0001.lzma
2022-02-17T00:12:31.149Z,1645056751.149 [DataOverHttps](INFO): Moved sent file to Logs/20220216T223859/Express0001.lzma.bak
2022-02-17T00:12:31.150Z,1645056751.150 [DataOverHttps](INFO): SBD MOMSN=16504425
2022-02-17T00:12:46.780Z,1645056766.780 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20220216T224124/Express0001.lzma
2022-02-17T00:12:47.773Z,1645056767.773 [DataOverHttps](INFO): Moved sent file to Logs/20220216T224124/Express0001.lzma.bak
2022-02-17T00:12:47.774Z,1645056767.774 [DataOverHttps](INFO): SBD MOMSN=16504448
2022-02-17T00:13:03.437Z,1645056783.437 [DataOverHttps](INFO): Sending 802 bytes from file Logs/20220216T235948/Express0001.lzma
2022-02-17T00:13:03.756Z,1645056783.756 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 4
2022-02-17T00:13:03.756Z,1645056783.756 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2022-02-17T00:13:03.758Z,1645056783.758 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 4
2022-02-17T00:13:03.758Z,1645056783.758 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2022-02-17T00:13:03.768Z,1645056783.768 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2022-02-17T00:13:03.769Z,1645056783.769 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2022-02-17T00:13:04.177Z,1645056784.177 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2022-02-17T00:13:04.177Z,1645056784.177 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 4
2022-02-17T00:13:04.177Z,1645056784.177 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2022-02-17T00:13:04.177Z,1645056784.177 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 4
2022-02-17T00:13:04.438Z,1645056784.438 [DataOverHttps](INFO): Moved sent file to Logs/20220216T235948/Express0001.lzma.bak
2022-02-17T00:13:04.438Z,1645056784.438 [DataOverHttps](INFO): SBD MOMSN=16504450
2022-02-17T00:13:04.560Z,1645056784.560 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2022-02-17T00:13:20.009Z,1645056800.009 [DataOverHttps](INFO): Sending 1316 bytes from file Logs/20220217T000050/Express0001.lzma
2022-02-17T00:13:21.010Z,1645056801.010 [DataOverHttps](INFO): Moved sent file to Logs/20220217T000050/Express0001.lzma.bak
2022-02-17T00:13:21.010Z,1645056801.010 [DataOverHttps](INFO): SBD MOMSN=16504481
2022-02-17T00:13:22.327Z,1645056802.327 [Default:CheckIn:Read_Iridium] Stopped
2022-02-17T00:13:22.327Z,1645056802.327 [Default:CheckIn:C.Wait] Running Loop=1
2022-02-17T00:13:22.327Z,1645056802.327 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-02-17T00:13:41.574Z,1645056821.574 [CommandExec](IMPORTANT): got command run ./Missions/Demo/DockingModeTest.xml
2022-02-17T00:13:41.575Z,1645056821.575 [MissionManager](INFO): Loading Mission from file: ./Missions/Demo/DockingModeTest.xml
2022-02-17T00:13:41.623Z,1645056821.623 [MissionManager](INFO): DefineArg DockingModeTest.TransponderCode = 2 count
2022-02-17T00:13:41.627Z,1645056821.627 [MissionManager](INFO): DefineArg DockingModeTest.TrackingUpdatePeriod = 2.500000 s
2022-02-17T00:13:41.632Z,1645056821.632 [MissionManager](INFO): DefineArg DockingModeTest.NumberOfPings = 1.000000 count
2022-02-17T00:13:41.668Z,1645056821.668 [MissionManager](INFO): DefineArg DockingModeTest.TrackingNumFixesLowPassFilter = 5.000000 count
2022-02-17T00:13:41.676Z,1645056821.676 [MissionManager](INFO): DefineArg DockingModeTest.losRateIIRFilterDecay = 0.000000 n/a
2022-02-17T00:13:41.772Z,1645056821.772 [DockingModeTest:Test:B.LineCapture](DEBUG): Construct.
2022-02-17T00:13:41.842Z,1645056821.842 [DockingModeTest:Test:B.LineCapture](DEBUG): Initializing internal variables to default values.
2022-02-17T00:13:41.842Z,1645056821.842 [DockingModeTest:Test:B.LineCapture](INFO): Transitioning guidance mode to: UNINITIALIZED
2022-02-17T00:13:41.850Z,1645056821.850 [DockingModeTest:Test:C.Wait](DEBUG): Construct Wait.
2022-02-17T00:13:41.858Z,1645056821.858 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Sensor="Tethys/Sensor"
       xmlns:Units="Tethys/Units"
       xmlns:Estimation="Tethys/Estimation"
       xmlns:Guidance="Tethys/Guidance"
       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/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="DockingModeTest">

       <DefineArg Name="TransponderCode"><Description>
           Transponder Address.
       </Description><Dock:Dock.transponderCode/></DefineArg>

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

       <DefineArg Name="NumberOfPings"><Description>
           Number of pings requested each time.
       </Description><Units:count/><Value>1</Value></DefineArg>

       <DefineArg Name="TrackingNumFixesLowPassFilter"><Description>
           Median filter bin size. Filters the contact estimated lat/lon position.
           Prefer odd number, set to 1 to disable filter.
       </Description><Units:count/><Value>5</Value></DefineArg>

       <DefineArg Name="losRateIIRFilterDecay"><Description>
           LineCapture single-pole IIR filter decay value.
           Filters line-of-sight (LOS) angle rotation rate.
           The Decay value should be btween 0 to 1, set to 0 disable filtering.
       </Description><Units:none/><Value>0.0</Value></DefineArg>


       <Timeout Duration="P15M"/>

       <Aggregate Id="Test">

           <Estimation:TrackAcousticContact>
               <Parallel/>
               <Setting><Estimation:TrackAcousticContact.contactLabelSetting/><Arg Name="TransponderCode"/></Setting>
               <Setting><Estimation:TrackAcousticContact.numberOfSamplesSetting/><Arg Name="NumberOfPings"/></Setting>
               <Setting><Estimation:TrackAcousticContact.updatePeriodSetting/><Arg Name="TrackingUpdatePeriod"/></Setting>
               <Setting><Estimation:TrackAcousticContact.numFixesLowPassSetting/><Arg Name="TrackingNumFixesLowPassFilter"/></Setting>
           </Estimation:TrackAcousticContact>

           <Dock:LineCapture>
               <Sequence/>
               <Setting><Dock:LineCapture.iirFilterDecay/><Arg Name="losRateIIRFilterDecay"/></Setting>
           </Dock:LineCapture>

           <Guidance:Wait>
               <Sequence/>
               <Setting><Guidance:Wait.duration/><Units:second/><Value>60</Value></Setting>
           </Guidance:Wait>

       </Aggregate>

</Mission>


2022-02-17T00:13:41.864Z,1645056821.864 [CommandExec](IMPORTANT): Running ./Missions/Demo/DockingModeTest.xml
2022-02-17T00:13:42.121Z,1645056822.121 [Default] Stopped
2022-02-17T00:13:42.121Z,1645056822.121 [Default](DEBUG): Aggregate::uninitialize Default
2022-02-17T00:13:42.122Z,1645056822.122 [Default:B.GoToSurface] Stopped
2022-02-17T00:13:42.122Z,1645056822.122 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2022-02-17T00:13:42.122Z,1645056822.122 [Default:CheckIn] Stopped
2022-02-17T00:13:42.122Z,1645056822.122 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-02-17T00:13:42.122Z,1645056822.122 [Default:CheckIn:C.Wait] Stopped
2022-02-17T00:13:42.122Z,1645056822.122 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-02-17T00:13:42.122Z,1645056822.122 [MissionManager](IMPORTANT): Started mission DockingModeTest
2022-02-17T00:13:42.122Z,1645056822.122 [DockingModeTest] Running Loop=1
2022-02-17T00:13:42.122Z,1645056822.122 [DockingModeTest](DEBUG): Aggregate::initialize DockingModeTest
2022-02-17T00:13:42.123Z,1645056822.123 [DockingModeTest:Test] Running Loop=1
2022-02-17T00:13:42.123Z,1645056822.123 [DockingModeTest:Test](DEBUG): Aggregate::initialize DockingModeTest:Test
2022-02-17T00:13:42.123Z,1645056822.123 [DockingModeTest:Test:A.] Running Loop=1
2022-02-17T00:13:42.123Z,1645056822.123 [DockingModeTest:Test:A.](INFO): Initializing TrackAcousticContact.
2022-02-17T00:13:42.123Z,1645056822.123 [DockingModeTest:Test:B.LineCapture] Running Loop=1
2022-02-17T00:13:42.123Z,1645056822.123 [DockingModeTest:Test:B.LineCapture](DEBUG): Initialize.
2022-02-17T00:13:42.123Z,1645056822.123 [DockingModeTest:Test:B.LineCapture](DEBUG): Initializing internal variables to default values.
2022-02-17T00:13:42.123Z,1645056822.123 [DockingModeTest:Test:B.LineCapture](INFO): Transitioning guidance mode to: UNINITIALIZED
2022-02-17T00:13:42.124Z,1645056822.124 [DockingModeTest:Test:B.LineCapture](INFO): Rollout timeout set to 900.00 sec.
2022-02-17T00:13:42.125Z,1645056822.125 [DockingModeTest:Test:B.LineCapture](IMPORTANT): IIR filter is initialized with decay: 0.00.
2022-02-17T00:13:42.125Z,1645056822.125 [DockingModeTest:Test:B.LineCapture](INFO): Transitioning guidance mode to: TERMINAL_GUIDANCE
2022-02-17T00:13:42.126Z,1645056822.126 [DockingModeTest:Test:A.] Running Loop=1
2022-02-17T00:13:42.127Z,1645056822.127 [DockingModeTest:Test:A.](DEBUG): Tracking...
2022-02-17T00:13:42.127Z,1645056822.127 [DockingModeTest:Test:A.](INFO): Tracking contact label: 2
2022-02-17T00:13:42.127Z,1645056822.127 [DockingModeTest:Test:A.](INFO): waiting for update period (2.500000 s) to elapse
2022-02-17T00:13:42.526Z,1645056822.526 [DockingModeTest:Test:A.](DEBUG): Tracking...
2022-02-17T00:13:42.526Z,1645056822.526 [DockingModeTest:Test:A.](INFO): Tracking contact label: 2
2022-02-17T00:13:42.526Z,1645056822.526 [DockingModeTest:Test:A.](INFO): waiting for update period (2.500000 s) to elapse
2022-02-17T00:13:42.942Z,1645056822.942 [DockingModeTest:Test:A.](DEBUG): Tracking...
2022-02-17T00:13:42.942Z,1645056822.942 [DockingModeTest:Test:A.](INFO): Tracking contact label: 2
2022-02-17T00:13:42.943Z,1645056822.943 [DockingModeTest:Test:A.](INFO): waiting for update period (2.500000 s) to elapse
2022-02-17T00:13:43.330Z,1645056823.330 [DockingModeTest:Test:A.](DEBUG): Tracking...
2022-02-17T00:13:43.330Z,1645056823.330 [DockingModeTest:Test:A.](INFO): Tracking contact label: 2
2022-02-17T00:13:43.330Z,1645056823.330 [DockingModeTest:Test:A.](INFO): waiting for update period (2.500000 s) to elapse
2022-02-17T00:13:43.759Z,1645056823.759 [DockingModeTest:Test:A.](DEBUG): Tracking...
2022-02-17T00:13:43.760Z,1645056823.760 [DockingModeTest:Test:A.](INFO): Tracking contact label: 2
2022-02-17T00:13:43.760Z,1645056823.760 [DockingModeTest:Test:A.](INFO): waiting for update period (2.500000 s) to elapse
2022-02-17T00:13:44.157Z,1645056824.157 [DockingModeTest:Test:A.](DEBUG): Tracking...
2022-02-17T00:13:44.157Z,1645056824.157 [DockingModeTest:Test:A.](INFO): Tracking contact label: 2
2022-02-17T00:13:44.157Z,1645056824.157 [DockingModeTest:Test:A.](INFO): waiting for update period (2.500000 s) to elapse
2022-02-17T00:13:44.579Z,1645056824.579 [DockingModeTest:Test:A.](DEBUG): Tracking...
2022-02-17T00:13:44.579Z,1645056824.579 [DockingModeTest:Test:A.](INFO): Tracking contact label: 2
2022-02-17T00:13:44.579Z,1645056824.579 [DockingModeTest:Test:A.](INFO): waiting for update period (2.500000 s) to elapse
2022-02-17T00:13:44.945Z,1645056824.945 [DockingModeTest:Test:A.](DEBUG): Tracking...
2022-02-17T00:13:44.945Z,1645056824.945 [DockingModeTest:Test:A.](INFO): Tracking contact label: 2
2022-02-17T00:13:44.946Z,1645056824.946 [DockingModeTest:Test:A.](INFO): update period (2.500000 s) has elapsed, querying...
2022-02-17T00:13:44.946Z,1645056824.946 [DockingModeTest:Test:A.](INFO): *** querying acoustic contact ***
2022-02-17T00:13:45.124Z,1645056825.124 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:45.125Z,1645056825.125 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:45.125Z,1645056825.125 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:45.356Z,1645056825.356 [DockingModeTest:Test:A.](DEBUG): Tracking...
2022-02-17T00:13:45.356Z,1645056825.356 [DockingModeTest:Test:A.](INFO): Tracking contact label: 2
2022-02-17T00:13:45.357Z,1645056825.357 [DockingModeTest:Test:A.](INFO): waiting for update period (2.500000 s) to elapse
2022-02-17T00:13:45.376Z,1645056825.376 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:45.376Z,1645056825.376 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:45.377Z,1645056825.377 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:45.628Z,1645056825.628 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:45.628Z,1645056825.628 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:45.629Z,1645056825.629 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:45.767Z,1645056825.767 [DockingModeTest:Test:A.](DEBUG): Tracking...
2022-02-17T00:13:45.768Z,1645056825.768 [DockingModeTest:Test:A.](INFO): Tracking contact label: 2
2022-02-17T00:13:45.768Z,1645056825.768 [DockingModeTest:Test:A.](INFO): waiting for update period (2.500000 s) to elapse
2022-02-17T00:13:45.880Z,1645056825.880 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:45.880Z,1645056825.880 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:45.881Z,1645056825.881 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:46.136Z,1645056826.136 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:46.136Z,1645056826.136 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:46.136Z,1645056826.136 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:46.199Z,1645056826.199 [DockingModeTest:Test:A.](DEBUG): Tracking...
2022-02-17T00:13:46.199Z,1645056826.199 [DockingModeTest:Test:A.](INFO): Tracking contact label: 2
2022-02-17T00:13:46.204Z,1645056826.204 [DockingModeTest:Test:A.](INFO): waiting for update period (2.500000 s) to elapse
2022-02-17T00:13:46.388Z,1645056826.388 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:46.388Z,1645056826.388 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:46.389Z,1645056826.389 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:46.618Z,1645056826.618 [DockingModeTest:Test:A.](DEBUG): Tracking...
2022-02-17T00:13:46.618Z,1645056826.618 [DockingModeTest:Test:A.](INFO): Tracking contact label: 2
2022-02-17T00:13:46.619Z,1645056826.619 [DockingModeTest:Test:A.](INFO): waiting for update period (2.500000 s) to elapse
2022-02-17T00:13:46.641Z,1645056826.641 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:46.641Z,1645056826.641 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:46.641Z,1645056826.641 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:46.892Z,1645056826.892 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:46.892Z,1645056826.892 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:46.893Z,1645056826.893 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:46.988Z,1645056826.988 [DockingModeTest:Test:A.](DEBUG): Tracking...
2022-02-17T00:13:46.988Z,1645056826.988 [DockingModeTest:Test:A.](INFO): Tracking contact label: 2
2022-02-17T00:13:46.989Z,1645056826.989 [DockingModeTest:Test:A.](INFO): waiting for update period (2.500000 s) to elapse
2022-02-17T00:13:47.145Z,1645056827.145 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:47.145Z,1645056827.145 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:47.145Z,1645056827.145 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:47.388Z,1645056827.388 [DockingModeTest:Test:A.](DEBUG): Tracking...
2022-02-17T00:13:47.388Z,1645056827.388 [DockingModeTest:Test:A.](INFO): Tracking contact label: 2
2022-02-17T00:13:47.389Z,1645056827.389 [DockingModeTest:Test:A.](INFO): waiting for update period (2.500000 s) to elapse
2022-02-17T00:13:47.399Z,1645056827.399 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:47.399Z,1645056827.399 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:47.399Z,1645056827.399 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:47.648Z,1645056827.648 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:47.648Z,1645056827.648 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:47.649Z,1645056827.649 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:47.799Z,1645056827.799 [DockingModeTest:Test:A.](DEBUG): Tracking...
2022-02-17T00:13:47.799Z,1645056827.799 [DockingModeTest:Test:A.](INFO): Tracking contact label: 2
2022-02-17T00:13:47.800Z,1645056827.800 [DockingModeTest:Test:A.](INFO): update period (2.500000 s) has elapsed, querying...
2022-02-17T00:13:47.800Z,1645056827.800 [DockingModeTest:Test:A.](INFO): *** querying acoustic contact ***
2022-02-17T00:13:47.900Z,1645056827.900 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:47.900Z,1645056827.900 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:47.901Z,1645056827.901 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:48.152Z,1645056828.152 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:48.153Z,1645056828.153 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:48.153Z,1645056828.153 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:48.179Z,1645056828.179 [DockingModeTest:Test:A.](DEBUG): Tracking...
2022-02-17T00:13:48.179Z,1645056828.179 [DockingModeTest:Test:A.](INFO): Tracking contact label: 2
2022-02-17T00:13:48.180Z,1645056828.180 [DockingModeTest:Test:A.](INFO): waiting for update period (2.500000 s) to elapse
2022-02-17T00:13:48.404Z,1645056828.404 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:48.404Z,1645056828.404 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:48.405Z,1645056828.405 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:48.586Z,1645056828.586 [DockingModeTest:Test:A.](DEBUG): Tracking...
2022-02-17T00:13:48.587Z,1645056828.587 [DockingModeTest:Test:A.](INFO): Tracking contact label: 2
2022-02-17T00:13:48.587Z,1645056828.587 [DockingModeTest:Test:A.](INFO): waiting for update period (2.500000 s) to elapse
2022-02-17T00:13:48.657Z,1645056828.657 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:48.657Z,1645056828.657 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:48.657Z,1645056828.657 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:48.908Z,1645056828.908 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:48.908Z,1645056828.908 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:48.909Z,1645056828.909 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:48.999Z,1645056828.999 [DockingModeTest:Test:A.](DEBUG): Tracking...
2022-02-17T00:13:48.000Z,1645056829.000 [DockingModeTest:Test:A.](INFO): Tracking contact label: 2
2022-02-17T00:13:49.000Z,1645056829.000 [DockingModeTest:Test:A.](INFO): waiting for update period (2.500000 s) to elapse
2022-02-17T00:13:49.160Z,1645056829.160 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:49.160Z,1645056829.160 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:49.161Z,1645056829.161 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:49.392Z,1645056829.392 [DockingModeTest:Test:A.](DEBUG): Tracking...
2022-02-17T00:13:49.392Z,1645056829.392 [DockingModeTest:Test:A.](INFO): Tracking contact label: 2
2022-02-17T00:13:49.393Z,1645056829.393 [DockingModeTest:Test:A.](INFO): waiting for update period (2.500000 s) to elapse
2022-02-17T00:13:49.413Z,1645056829.413 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:49.413Z,1645056829.413 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:49.413Z,1645056829.413 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:49.664Z,1645056829.664 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:49.664Z,1645056829.664 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:49.665Z,1645056829.665 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:49.830Z,1645056829.830 [DockingModeTest:Test:A.](DEBUG): Tracking...
2022-02-17T00:13:49.830Z,1645056829.830 [DockingModeTest:Test:A.](INFO): Tracking contact label: 2
2022-02-17T00:13:49.831Z,1645056829.831 [DockingModeTest:Test:A.](INFO): waiting for update period (2.500000 s) to elapse
2022-02-17T00:13:49.916Z,1645056829.916 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:49.917Z,1645056829.917 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:49.917Z,1645056829.917 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:50.169Z,1645056830.169 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:50.169Z,1645056830.169 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:50.169Z,1645056830.169 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:50.229Z,1645056830.229 [DockingModeTest:Test:A.](DEBUG): Tracking...
2022-02-17T00:13:50.230Z,1645056830.230 [DockingModeTest:Test:A.](INFO): Tracking contact label: 2
2022-02-17T00:13:50.230Z,1645056830.230 [DockingModeTest:Test:A.](INFO): waiting for update period (2.500000 s) to elapse
2022-02-17T00:13:50.421Z,1645056830.421 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:50.421Z,1645056830.421 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:50.421Z,1645056830.421 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:50.617Z,1645056830.617 [DockingModeTest:Test:A.](DEBUG): Tracking...
2022-02-17T00:13:50.617Z,1645056830.617 [DockingModeTest:Test:A.](INFO): Tracking contact label: 2
2022-02-17T00:13:50.618Z,1645056830.618 [DockingModeTest:Test:A.](INFO): update period (2.500000 s) has elapsed, querying...
2022-02-17T00:13:50.618Z,1645056830.618 [DockingModeTest:Test:A.](INFO): *** querying acoustic contact ***
2022-02-17T00:13:50.672Z,1645056830.672 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:50.672Z,1645056830.672 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:50.673Z,1645056830.673 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:50.925Z,1645056830.925 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:50.925Z,1645056830.925 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:50.925Z,1645056830.925 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:51.003Z,1645056831.003 [DockingModeTest:Test:A.](DEBUG): Tracking...
2022-02-17T00:13:51.004Z,1645056831.004 [DockingModeTest:Test:A.](INFO): Tracking contact label: 2
2022-02-17T00:13:51.004Z,1645056831.004 [DockingModeTest:Test:A.](INFO): waiting for update period (2.500000 s) to elapse
2022-02-17T00:13:51.176Z,1645056831.176 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:51.176Z,1645056831.176 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:51.177Z,1645056831.177 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:51.413Z,1645056831.413 [DockingModeTest:Test:A.](DEBUG): Tracking...
2022-02-17T00:13:51.414Z,1645056831.414 [DockingModeTest:Test:A.](INFO): Tracking contact label: 2
2022-02-17T00:13:51.414Z,1645056831.414 [DockingModeTest:Test:A.](INFO): waiting for update period (2.500000 s) to elapse
2022-02-17T00:13:51.428Z,1645056831.428 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:51.429Z,1645056831.429 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:51.429Z,1645056831.429 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:51.680Z,1645056831.680 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:51.680Z,1645056831.680 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:51.681Z,1645056831.681 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:51.825Z,1645056831.825 [DockingModeTest:Test:A.](DEBUG): Tracking...
2022-02-17T00:13:51.825Z,1645056831.825 [DockingModeTest:Test:A.](INFO): Tracking contact label: 2
2022-02-17T00:13:51.826Z,1645056831.826 [DockingModeTest:Test:A.](INFO): waiting for update period (2.500000 s) to elapse
2022-02-17T00:13:51.932Z,1645056831.932 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:51.932Z,1645056831.932 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:51.933Z,1645056831.933 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:52.184Z,1645056832.184 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:52.184Z,1645056832.184 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:52.185Z,1645056832.185 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:52.218Z,1645056832.218 [DockingModeTest:Test:A.](DEBUG): Tracking...
2022-02-17T00:13:52.218Z,1645056832.218 [DockingModeTest:Test:A.](INFO): Tracking contact label: 2
2022-02-17T00:13:52.218Z,1645056832.218 [DockingModeTest:Test:A.](INFO): waiting for update period (2.500000 s) to elapse
2022-02-17T00:13:52.436Z,1645056832.436 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:52.436Z,1645056832.436 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:52.437Z,1645056832.437 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:52.651Z,1645056832.651 [DockingModeTest:Test:A.](DEBUG): Tracking...
2022-02-17T00:13:52.651Z,1645056832.651 [DockingModeTest:Test:A.](INFO): Tracking contact label: 2
2022-02-17T00:13:52.652Z,1645056832.652 [DockingModeTest:Test:A.](INFO): waiting for update period (2.500000 s) to elapse
2022-02-17T00:13:52.689Z,1645056832.689 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:52.689Z,1645056832.689 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:52.689Z,1645056832.689 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:52.940Z,1645056832.940 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:52.940Z,1645056832.940 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:52.941Z,1645056832.941 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:53.044Z,1645056833.044 [DockingModeTest:Test:A.](DEBUG): Tracking...
2022-02-17T00:13:53.045Z,1645056833.045 [DockingModeTest:Test:A.](INFO): Tracking contact label: 2
2022-02-17T00:13:53.045Z,1645056833.045 [DockingModeTest:Test:A.](INFO): waiting for update period (2.500000 s) to elapse
2022-02-17T00:13:53.193Z,1645056833.193 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:53.193Z,1645056833.193 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:53.193Z,1645056833.193 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:53.444Z,1645056833.444 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:53.444Z,1645056833.444 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:53.445Z,1645056833.445 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:53.455Z,1645056833.455 [DockingModeTest:Test:A.](DEBUG): Tracking...
2022-02-17T00:13:53.455Z,1645056833.455 [DockingModeTest:Test:A.](INFO): Tracking contact label: 2
2022-02-17T00:13:53.456Z,1645056833.456 [DockingModeTest:Test:A.](INFO): update period (2.500000 s) has elapsed, querying...
2022-02-17T00:13:53.456Z,1645056833.456 [DockingModeTest:Test:A.](INFO): *** querying acoustic contact ***
2022-02-17T00:13:53.697Z,1645056833.697 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:53.697Z,1645056833.697 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:53.697Z,1645056833.697 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:53.839Z,1645056833.839 [DockingModeTest:Test:A.](DEBUG): Tracking...
2022-02-17T00:13:53.839Z,1645056833.839 [DockingModeTest:Test:A.](INFO): Tracking contact label: 2
2022-02-17T00:13:53.840Z,1645056833.840 [DockingModeTest:Test:A.](INFO): waiting for update period (2.500000 s) to elapse
2022-02-17T00:13:53.948Z,1645056833.948 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:53.948Z,1645056833.948 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:53.949Z,1645056833.949 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:54.200Z,1645056834.200 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:54.200Z,1645056834.200 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:54.201Z,1645056834.201 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:54.261Z,1645056834.261 [DockingModeTest:Test:A.](DEBUG): Tracking...
2022-02-17T00:13:54.262Z,1645056834.262 [DockingModeTest:Test:A.](INFO): Tracking contact label: 2
2022-02-17T00:13:54.262Z,1645056834.262 [DockingModeTest:Test:A.](INFO): waiting for update period (2.500000 s) to elapse
2022-02-17T00:13:54.452Z,1645056834.452 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:54.452Z,1645056834.452 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:54.453Z,1645056834.453 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:54.651Z,1645056834.651 [DockingModeTest:Test:A.](DEBUG): Tracking...
2022-02-17T00:13:54.651Z,1645056834.651 [DockingModeTest:Test:A.](INFO): Tracking contact label: 2
2022-02-17T00:13:54.652Z,1645056834.652 [DockingModeTest:Test:A.](INFO): waiting for update period (2.500000 s) to elapse
2022-02-17T00:13:54.705Z,1645056834.705 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:54.705Z,1645056834.705 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:54.705Z,1645056834.705 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:54.956Z,1645056834.956 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:54.956Z,1645056834.956 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:54.957Z,1645056834.957 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:55.071Z,1645056835.071 [DockingModeTest:Test:A.](DEBUG): Tracking...
2022-02-17T00:13:55.071Z,1645056835.071 [DockingModeTest:Test:A.](INFO): Tracking contact label: 2
2022-02-17T00:13:55.072Z,1645056835.072 [DockingModeTest:Test:A.](INFO): waiting for update period (2.500000 s) to elapse
2022-02-17T00:13:55.208Z,1645056835.208 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:55.208Z,1645056835.208 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:55.209Z,1645056835.209 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:55.461Z,1645056835.461 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:55.461Z,1645056835.461 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:55.461Z,1645056835.461 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:55.501Z,1645056835.501 [DockingModeTest:Test:A.](DEBUG): Tracking...
2022-02-17T00:13:55.501Z,1645056835.501 [DockingModeTest:Test:A.](INFO): Tracking contact label: 2
2022-02-17T00:13:55.501Z,1645056835.501 [DockingModeTest:Test:A.](INFO): waiting for update period (2.500000 s) to elapse
2022-02-17T00:13:55.715Z,1645056835.715 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:55.715Z,1645056835.715 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:55.716Z,1645056835.716 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:55.857Z,1645056835.857 [DockingModeTest:Test:A.](DEBUG): Tracking...
2022-02-17T00:13:55.857Z,1645056835.857 [DockingModeTest:Test:A.](INFO): Tracking contact label: 2
2022-02-17T00:13:55.857Z,1645056835.857 [DockingModeTest:Test:A.](INFO): waiting for update period (2.500000 s) to elapse
2022-02-17T00:13:55.964Z,1645056835.964 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:55.964Z,1645056835.964 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:55.965Z,1645056835.965 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:56.217Z,1645056836.217 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:56.217Z,1645056836.217 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:56.217Z,1645056836.217 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:56.296Z,1645056836.296 [DockingModeTest:Test:A.](DEBUG): Tracking...
2022-02-17T00:13:56.296Z,1645056836.296 [DockingModeTest:Test:A.](INFO): Tracking contact label: 2
2022-02-17T00:13:56.297Z,1645056836.297 [DockingModeTest:Test:A.](INFO): update period (2.500000 s) has elapsed, querying...
2022-02-17T00:13:56.297Z,1645056836.297 [DockingModeTest:Test:A.](INFO): *** querying acoustic contact ***
2022-02-17T00:13:56.468Z,1645056836.468 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:56.468Z,1645056836.468 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:56.469Z,1645056836.469 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:56.688Z,1645056836.688 [DockingModeTest:Test:A.](DEBUG): Tracking...
2022-02-17T00:13:56.688Z,1645056836.688 [DockingModeTest:Test:A.](INFO): Tracking contact label: 2
2022-02-17T00:13:56.689Z,1645056836.689 [DockingModeTest:Test:A.](INFO): waiting for update period (2.500000 s) to elapse
2022-02-17T00:13:56.721Z,1645056836.721 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:56.721Z,1645056836.721 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:56.721Z,1645056836.721 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:56.973Z,1645056836.973 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:56.973Z,1645056836.973 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:56.973Z,1645056836.973 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:57.083Z,1645056837.083 [DockingModeTest:Test:A.](DEBUG): Tracking...
2022-02-17T00:13:57.083Z,1645056837.083 [DockingModeTest:Test:A.](INFO): Tracking contact label: 2
2022-02-17T00:13:57.084Z,1645056837.084 [DockingModeTest:Test:A.](INFO): waiting for update period (2.500000 s) to elapse
2022-02-17T00:13:57.224Z,1645056837.224 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:57.224Z,1645056837.224 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:57.225Z,1645056837.225 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:57.476Z,1645056837.476 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:57.476Z,1645056837.476 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:57.477Z,1645056837.477 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:57.495Z,1645056837.495 [DockingModeTest:Test:A.](DEBUG): Tracking...
2022-02-17T00:13:57.495Z,1645056837.495 [DockingModeTest:Test:A.](INFO): Tracking contact label: 2
2022-02-17T00:13:57.496Z,1645056837.496 [DockingModeTest:Test:A.](INFO): waiting for update period (2.500000 s) to elapse
2022-02-17T00:13:57.728Z,1645056837.728 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:57.728Z,1645056837.728 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:57.729Z,1645056837.729 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:57.894Z,1645056837.894 [DockingModeTest:Test:A.](DEBUG): Tracking...
2022-02-17T00:13:57.894Z,1645056837.894 [DockingModeTest:Test:A.](INFO): Tracking contact label: 2
2022-02-17T00:13:57.895Z,1645056837.895 [DockingModeTest:Test:A.](INFO): waiting for update period (2.500000 s) to elapse
2022-02-17T00:13:57.981Z,1645056837.981 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:57.981Z,1645056837.981 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:57.981Z,1645056837.981 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:58.232Z,1645056838.232 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:58.232Z,1645056838.232 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:58.233Z,1645056838.233 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:58.302Z,1645056838.302 [DockingModeTest:Test:A.](DEBUG): Tracking...
2022-02-17T00:13:58.302Z,1645056838.302 [DockingModeTest:Test:A.](INFO): Tracking contact label: 2
2022-02-17T00:13:58.303Z,1645056838.303 [DockingModeTest:Test:A.](INFO): waiting for update period (2.500000 s) to elapse
2022-02-17T00:13:58.484Z,1645056838.484 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:58.484Z,1645056838.484 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:58.485Z,1645056838.485 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:58.683Z,1645056838.683 [DockingModeTest:Test:A.](DEBUG): Tracking...
2022-02-17T00:13:58.683Z,1645056838.683 [DockingModeTest:Test:A.](INFO): Tracking contact label: 2
2022-02-17T00:13:58.683Z,1645056838.683 [DockingModeTest:Test:A.](INFO): waiting for update period (2.500000 s) to elapse
2022-02-17T00:13:58.737Z,1645056838.737 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:58.737Z,1645056838.737 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:58.737Z,1645056838.737 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:58.988Z,1645056838.988 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:58.989Z,1645056838.989 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:58.989Z,1645056838.989 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:59.082Z,1645056839.082 [DockingModeTest:Test:A.](DEBUG): Tracking...
2022-02-17T00:13:59.083Z,1645056839.083 [DockingModeTest:Test:A.](INFO): Tracking contact label: 2
2022-02-17T00:13:59.083Z,1645056839.083 [DockingModeTest:Test:A.](INFO): update period (2.500000 s) has elapsed, querying...
2022-02-17T00:13:59.083Z,1645056839.083 [DockingModeTest:Test:A.](INFO): *** querying acoustic contact ***
2022-02-17T00:13:59.241Z,1645056839.241 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:59.241Z,1645056839.241 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:59.241Z,1645056839.241 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:59.492Z,1645056839.492 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:59.493Z,1645056839.493 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:59.493Z,1645056839.493 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:59.507Z,1645056839.507 [DockingModeTest:Test:A.](DEBUG): Tracking...
2022-02-17T00:13:59.507Z,1645056839.507 [DockingModeTest:Test:A.](INFO): Tracking contact label: 2
2022-02-17T00:13:59.512Z,1645056839.512 [DockingModeTest:Test:A.](INFO): waiting for update period (2.500000 s) to elapse
2022-02-17T00:13:59.609Z,1645056839.609 [CommandExec](IMPORTANT): got command stop
2022-02-17T00:13:59.609Z,1645056839.609 [Supervisor](INFO): Stop Mission called by CommandExec::commandStop
2022-02-17T00:13:59.744Z,1645056839.744 [DAT](INFO): ****** received valid address query ******
2022-02-17T00:13:59.745Z,1645056839.745 [DAT](INFO): ****** received valid ping request ******
2022-02-17T00:13:59.745Z,1645056839.745 [DAT](INFO): Querying Benthos address 2 with one ping in standard two-way mode.
2022-02-17T00:13:59.923Z,1645056839.923 [DockingModeTest:Test:A.](DEBUG): Tracking...
2022-02-17T00:13:59.923Z,1645056839.923 [DockingModeTest:Test:A.](INFO): Tracking contact label: 2
2022-02-17T00:13:59.928Z,1645056839.928 [DockingModeTest:Test:A.](INFO): waiting for update period (2.500000 s) to elapse
2022-02-17T00:13:59.928Z,1645056839.928 [MissionManager](INFO): MissionManager is completed.
2022-02-17T00:13:59.928Z,1645056839.928 [MissionManager](INFO): Uninitializing Mission DockingModeTest
2022-02-17T00:13:59.929Z,1645056839.929 [DockingModeTest] Stopped
2022-02-17T00:13:59.929Z,1645056839.929 [DockingModeTest](DEBUG): Aggregate::uninitialize DockingModeTest
2022-02-17T00:13:59.929Z,1645056839.929 [DockingModeTest:Test] Stopped
2022-02-17T00:13:59.929Z,1645056839.929 [DockingModeTest:Test](DEBUG): Aggregate::uninitialize DockingModeTest:Test
2022-02-17T00:13:59.929Z,1645056839.929 [DockingModeTest:Test:A.] Stopped
2022-02-17T00:13:59.929Z,1645056839.929 [DockingModeTest:Test:A.](DEBUG): Uninitializing TrackAcousticContact.
2022-02-17T00:13:59.929Z,1645056839.929 [DockingModeTest:Test:B.LineCapture] Stopped
2022-02-17T00:13:59.929Z,1645056839.929 [DockingModeTest:Test:B.LineCapture](INFO): Transitioning guidance mode to: UNINITIALIZED
2022-02-17T00:14:00.330Z,1645056840.330 [MissionManager](IMPORTANT): Started mission Default
2022-02-17T00:14:00.330Z,1645056840.330 [Default] Running Loop=1
2022-02-17T00:14:00.330Z,1645056840.330 [Default](DEBUG): Aggregate::initialize Default
2022-02-17T00:14:00.330Z,1645056840.330 [Default:B.GoToSurface] Running Loop=1
2022-02-17T00:14:00.330Z,1645056840.330 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2022-02-17T00:14:00.331Z,1645056840.331 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2022-02-17T00:14:00.331Z,1645056840.331 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2022-02-17T00:14:00.331Z,1645056840.331 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2022-02-17T00:14:00.336Z,1645056840.336 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2022-02-17T00:14:00.337Z,1645056840.337 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2022-02-17T00:14:00.337Z,1645056840.337 [Default:A.Wait] Running Loop=1
2022-02-17T00:14:00.337Z,1645056840.337 [Default:A.Wait](DEBUG): Initialize Wait Component.
2022-02-17T00:14:03.029Z,1645056843.029 [DAT](INFO): DAT read: Forwarding Delay UpTx time:00:14:00.7939

2022-02-17T00:14:03.029Z,1645056843.029 [DAT](INFO): unknown deviceResponse_: Forwarding Delay UpTx time:00:14:00.7939

2022-02-17T00:14:11.780Z,1645056851.780 [CommandExec](IMPORTANT): got command quit
2022-02-17T00:14:12.784Z,1645056852.784 [CommandExec ThreadHandler](INFO): Uninitializing protected caller thread.
2022-02-17T00:14:12.784Z,1645056852.784 [CommandExec](INFO): Uninitializing the command executive.
2022-02-17T00:14:12.784Z,1645056852.784 [CommandExec](INFO): Uninitializing the command scheduler.
2022-02-17T00:14:12.784Z,1645056852.784 [CommandExec ThreadHandler](INFO): Thread cancelled.
2022-02-17T00:14:12.823Z,1645056852.823 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2022-02-17T00:14:12.823Z,1645056852.823 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2022-02-17T00:14:12.824Z,1645056852.824 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2022-02-17T00:14:12.824Z,1645056852.824 [NavChartDb](INFO): Join timeout helper Thread ID is 6983
2022-02-17T00:14:13.188Z,1645056853.188 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2022-02-17T00:14:13.188Z,1645056853.188 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2022-02-17T00:14:13.192Z,1645056853.192 [ComponentRegistry](INFO): Shutting down DAT ThreadHandler
2022-02-17T00:14:13.192Z,1645056853.192 [DAT ThreadHandler](INFO): Thread cancelled.
2022-02-17T00:14:13.192Z,1645056853.192 [DAT](INFO): Join timeout helper Thread ID is 6984
2022-02-17T00:14:13.364Z,1645056853.364 [DAT](INFO): Powering down
2022-02-17T00:14:13.436Z,1645056853.436 [DAT ThreadHandler](INFO): Uninitializing protected caller thread.
2022-02-17T00:14:13.437Z,1645056853.437 [DAT](INFO): Powering down
2022-02-17T00:14:13.437Z,1645056853.437 [DAT ThreadHandler](INFO): Thread cancelled.
2022-02-17T00:14:13.441Z,1645056853.441 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2022-02-17T00:14:13.441Z,1645056853.441 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2022-02-17T00:14:13.442Z,1645056853.442 [Radio_Surface](INFO): Join timeout helper Thread ID is 6985
2022-02-17T00:14:13.635Z,1645056853.635 [Default:A.Wait](INFO): Done Waiting.
2022-02-17T00:14:13.635Z,1645056853.635 [Default:A.Wait] Stopped
2022-02-17T00:14:13.635Z,1645056853.635 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2022-02-17T00:14:13.724Z,1645056853.724 [Radio_Surface](INFO): Powering down
2022-02-17T00:14:13.725Z,1645056853.725 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2022-02-17T00:14:13.725Z,1645056853.725 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2022-02-17T00:14:13.748Z,1645056853.748 [ComponentRegistry](INFO): Shutting down Onboard ThreadHandler
2022-02-17T00:14:13.749Z,1645056853.749 [Onboard ThreadHandler](INFO): Thread cancelled.
2022-02-17T00:14:13.749Z,1645056853.749 [Onboard](INFO): Join timeout helper Thread ID is 6986
2022-02-17T00:14:14.042Z,1645056854.042 [Default:CheckIn] Running Loop=1
2022-02-17T00:14:14.042Z,1645056854.042 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-02-17T00:14:14.042Z,1645056854.042 [Default:CheckIn:Read_GPS] Running Loop=1
2022-02-17T00:14:14.076Z,1645056854.076 [DataOverHttps](INFO): Radio surface powered OFF, will not connect.
2022-02-17T00:14:16.148Z,1645056856.148 [Onboard ThreadHandler](INFO): Uninitializing protected caller thread.
2022-02-17T00:14:16.148Z,1645056856.148 [Onboard ThreadHandler](INFO): Thread cancelled.
2022-02-17T00:14:16.156Z,1645056856.156 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2022-02-17T00:14:16.156Z,1645056856.156 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2022-02-17T00:14:16.156Z,1645056856.156 [DataOverHttps](INFO): Join timeout helper Thread ID is 6987
2022-02-17T00:14:17.100Z,1645056857.100 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2022-02-17T00:14:17.100Z,1645056857.100 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2022-02-17T00:14:17.113Z,1645056857.113 [ComponentRegistry](INFO): Shutting down BackseatComponent ThreadHandler
2022-02-17T00:14:17.113Z,1645056857.113 [BackseatComponent ThreadHandler](INFO): Thread cancelled.
2022-02-17T00:14:17.113Z,1645056857.113 [BackseatComponent](INFO): Join timeout helper Thread ID is 6988
2022-02-17T00:14:17.120Z,1645056857.120 [BackseatComponent ThreadHandler](INFO): Uninitializing protected caller thread.
2022-02-17T00:14:17.120Z,1645056857.120 [BackseatComponent ThreadHandler](INFO): Thread cancelled.
2022-02-17T00:14:17.142Z,1645056857.142 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2022-02-17T00:14:17.143Z,1645056857.143 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2022-02-17T00:14:17.143Z,1645056857.143 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 6989
2022-02-17T00:14:17.168Z,1645056857.168 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread.
2022-02-17T00:14:17.168Z,1645056857.168 [WetLabsBB2FL](INFO): Powering down
2022-02-17T00:14:17.169Z,1645056857.169 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2022-02-17T00:14:17.180Z,1645056857.180 [ComponentRegistry](INFO): Shutting down CTD_Seabird ThreadHandler
2022-02-17T00:14:17.181Z,1645056857.181 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2022-02-17T00:14:17.181Z,1645056857.181 [CTD_Seabird](INFO): Join timeout helper Thread ID is 6990
2022-02-17T00:14:17.784Z,1645056857.784 [CTD_Seabird](INFO): Powering down
2022-02-17T00:14:17.796Z,1645056857.796 [CTD_Seabird ThreadHandler](INFO): Uninitializing protected caller thread.
2022-02-17T00:14:17.796Z,1645056857.796 [CTD_Seabird](INFO): Powering down
2022-02-17T00:14:17.808Z,1645056857.808 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2022-02-17T00:14:17.819Z,1645056857.819 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2022-02-17T00:14:17.819Z,1645056857.819 [logger ThreadHandler](INFO): Thread cancelled.
2022-02-17T00:14:17.819Z,1645056857.819 [logger](INFO): Join timeout helper Thread ID is 6991
2022-02-17T00:14:17.845Z,1645056857.845 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2022-02-17T00:14:17.845Z,1645056857.845 [logger ThreadHandler](INFO): Thread cancelled.
2022-02-17T00:14:17.856Z,1645056857.856 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2022-02-17T00:14:17.857Z,1645056857.857 [CommandLine ThreadHandler](INFO): Thread cancelled.
2022-02-17T00:14:17.857Z,1645056857.857 [CommandLine](INFO): Join timeout helper Thread ID is 6992
2022-02-17T00:14:17.896Z,1645056857.896 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2022-02-17T00:14:17.896Z,1645056857.896 [CommandLine ThreadHandler](INFO): Thread cancelled.
2022-02-17T00:14:17.916Z,1645056857.916 [ComponentRegistry](INFO): Shutting down CommandExec ThreadHandler
2022-02-17T00:14:17.917Z,1645056857.917 [CommandExec ThreadHandler](INFO): Thread cancelled.
2022-02-17T00:14:17.917Z,1645056857.917 [CommandExec](INFO): Join timeout helper Thread ID is 6993
2022-02-17T00:14:17.918Z,1645056857.918 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2022-02-17T00:14:17.918Z,1645056857.918 [controlThread ThreadHandler](INFO): Thread cancelled.
2022-02-17T00:14:17.919Z,1645056857.919 [controlThread](INFO): Join timeout helper Thread ID is 6994
2022-02-17T00:14:18.045Z,1645056858.045 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2022-02-17T00:14:18.045Z,1645056858.045 [controlThread](DEBUG): Uninitializing ControlThread
2022-02-17T00:14:18.046Z,1645056858.046 [AHRS_M2](INFO): Powering down
2022-02-17T00:14:18.116Z,1645056858.116 [NAL9602](INFO): Powering down
2022-02-17T00:14:18.118Z,1645056858.118 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2022-02-17T00:14:18.119Z,1645056858.119 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2022-02-17T00:14:18.120Z,1645056858.120 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2022-02-17T00:14:18.120Z,1645056858.120 [MissionManager](INFO): Uninitializing Mission Default
2022-02-17T00:14:18.120Z,1645056858.120 [Default] Stopped
2022-02-17T00:14:18.121Z,1645056858.121 [Default](DEBUG): Aggregate::uninitialize Default
2022-02-17T00:14:18.121Z,1645056858.121 [Default:B.GoToSurface] Stopped
2022-02-17T00:14:18.121Z,1645056858.121 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2022-02-17T00:14:18.121Z,1645056858.121 [Default:CheckIn] Stopped
2022-02-17T00:14:18.121Z,1645056858.121 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-02-17T00:14:18.121Z,1645056858.121 [Default:CheckIn:Read_GPS] Stopped
2022-02-17T00:14:18.123Z,1645056858.123 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2022-02-17T00:14:18.124Z,1645056858.124 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2022-02-17T00:14:18.124Z,1645056858.124 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2022-02-17T00:14:18.125Z,1645056858.125 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2022-02-17T00:14:18.125Z,1645056858.125 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2022-02-17T00:14:18.125Z,1645056858.125 [BuoyancyServo](INFO): Powering down
2022-02-17T00:14:18.140Z,1645056858.140 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2022-02-17T00:14:18.140Z,1645056858.140 [ElevatorServo](INFO): Powering down
2022-02-17T00:14:18.141Z,1645056858.141 [MassServo](DEBUG): Uninitialize Mass Servo.
2022-02-17T00:14:18.141Z,1645056858.141 [MassServo](INFO): Powering down
2022-02-17T00:14:18.142Z,1645056858.142 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2022-02-17T00:14:18.142Z,1645056858.142 [RudderServo](INFO): Powering down
2022-02-17T00:14:18.143Z,1645056858.143 [ThrusterHE](DEBUG): Uninitialize Thruster Servo.
2022-02-17T00:14:18.143Z,1645056858.143 [ThrusterHE](INFO): Powering down
2022-02-17T00:14:18.144Z,1645056858.144 [SBIT](DEBUG): Uninitialize SBIT Component.
2022-02-17T00:14:18.144Z,1645056858.144 [IBIT](DEBUG): Uninitialize IBIT Component.
2022-02-17T00:14:18.144Z,1645056858.144 [CBIT](DEBUG): Uninitialize CBIT Component.
2022-02-17T00:14:18.144Z,1645056858.144 [CBIT](DEBUG): Powering off loads.
2022-02-17T00:14:18.156Z,1645056858.156 [CBIT](DEBUG): Disabling WDT.
2022-02-17T00:14:18.168Z,1645056858.168 [CBIT](DEBUG): Opening all GF detection circuits.
2022-02-17T00:14:18.169Z,1645056858.169 [controlThread ThreadHandler](INFO): Thread cancelled.
2022-02-17T00:14:18.198Z,1645056858.198 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2022-02-17T00:14:18.202Z,1645056858.202 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2022-02-17T00:14:18.245Z,1645056858.245 [DAT ThreadHandler](INFO): Thread cancelled.
2022-02-17T00:14:18.250Z,1645056858.250 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2022-02-17T00:14:18.252Z,1645056858.252 [Onboard ThreadHandler](INFO): Thread cancelled.
2022-02-17T00:14:18.257Z,1645056858.257 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2022-02-17T00:14:18.302Z,1645056858.302 [BackseatComponent ThreadHandler](INFO): Thread cancelled.
2022-02-17T00:14:18.342Z,1645056858.342 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2022-02-17T00:14:18.407Z,1645056858.407 [logger ThreadHandler](INFO): Thread cancelled.